In async http requests duration for every single request is not shown correctly

Viewed 120

I am testing async http requests using NodeJs 14 and AWS Lambda. So, I am doing 100 asynchronous http GET requests and trying measure duration for every single request. Total duration: 5632.74 ms.

  async makeRequests() {
    const axList = []

    for (const item of this.targets) {
        const {url, method} = item
        const config = {url, method}

        const stat = {
            startTime: this.getTime(),
            duration: 0,
            status: 0,
            response: null
        }

        const ax = axios.create()

        ax.interceptors.request.use((config) => {
            config.headers['startTime'] = this.getTime().toString();

            return config
        })

        ax.interceptors.response.use((response) => {
            const currentTime = this.getTime()
            const startTime = response.config.headers['startTime']
            response.headers['duration'] = (currentTime - startTime).toString()

            return response
        })

        const axItem = ax.request(config)
            .then((resp) => {
                const {status, data} = resp;

                stat.duration = resp.headers['duration']
                stat.response = data
                stat.status = status
            })
            .catch((error) => {
                console.log(error)
            })
            .finally(() => {
                this.reponses.push(stat)
            })

        axList.push(axItem)
    }

    await axios.all(axList)

    return this.reponses
}

In this case All requests are asynchronous but duration for every request is not correct or unexpected. Response logs:

  {
    "startTime": 1634169624637,
    "duration": "4063",
    "status": 200,
    "response": {
        "data": "OK"
    }
  },
  {
    "startTime": 1634169624638,
    "duration": "4120",
    "status": 200,
    "response": {
        "data": "OK"
    }
  }, 
  // .... + 97 logs
  {
    "startTime": 1634169624837,
    "duration": "5341",
    "status": 200,
    "response": {
      "data": "OK"
    }
  }

But when I do request synchronously by blocking every request using await inside the loop. I get real duration time for every request.

    async makeRequests() {
        for (const item of this.targets) {
            const {url, method} = item
            const config = {url, method}

            const stat = {
                startTime: this.getTime(),
                duration: 0,
                status: 0,
                response: null
            }

            const ax = axios.create()

            ax.interceptors.request.use((config) => {
                config.headers['startTime'] = this.getTime().toString();

                return config
            })

            ax.interceptors.response.use((response) => {
                const currentTime = this.getTime()
                const startTime = response.config.headers['startTime']
                response.headers['duration'] = (currentTime - startTime).toString()

                return response
            })

            await ax.request(config)
                .then((resp) => {
                    const {status, data} = resp;

                    stat.duration = resp.headers['duration']
                    stat.response = data
                    stat.status = status
                })
                .catch((error) => {
                    console.log(error)
                })
                .finally(() => {
                    this.reponses.push(stat)
                })
        }

        return this.reponses
    }

The duration for every request is realistic now. But it works synchronously which is bad and Total duration much more.

{
    "startTime": 1634162343040,
    "duration": "95",
    "status": 200,
    "response": {
        "data": "OK"
    }
},
{
    "startTime": 1634162343135,
    "duration": "44",
    "status": 200,
    "response": {
        "data": "OK"
    }
},
// .... + 97 logs
{
    "startTime": 1634162349596,
    "duration": "83",
    "status": 200,
    "response": {
        "data": "OK"
    }
}

What can I do for getting correct duration time for every request but at the same time it should be asynchronously ?

1 Answers

I have figured out the root cause of issue. With first method everthing is okay. The problem was in memory usage. My lambda memory was set 128 MB and it was not enough for executing 100 request asyncronously.

So, I have increased memory to 10240 MBand reduced request count to 20. Then response is expected and all requests are asyncronously.

Response logs:

{
    "startTime": 1634334790699,
    "duration": 32,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790704,
    "duration": 28,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790701,
    "duration": 31,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790708,
    "duration": 25,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790706,
    "duration": 28,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790698,
    "duration": 36,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790702,
    "duration": 33,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790696,
    "duration": 40,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790703,
    "duration": 34,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790701,
    "duration": 38,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790700,
    "duration": 43,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790698,
    "duration": 47,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790705,
    "duration": 41,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790704,
    "duration": 42,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790702,
    "duration": 45,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790699,
    "duration": 48,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790709,
    "duration": 39,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790706,
    "duration": 42,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790707,
    "duration": 42,
    "status": 200,
    "response": {
        "data": "OK"
    }
},{
    "startTime": 1634334790705,
    "duration": 116,
    "status": 200,
    "response": {
        "data": "OK"
    }
}

Related