Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Many queries from multiple calls to an Express handler are all executed before any query result arrives #1447

Closed
joerg-walter-de opened this issue Dec 12, 2022 · 2 comments
Closed

Many queries from multiple calls to an Express handler are all executed before any query result arrives #1447

joerg-walter-de opened this issue Dec 12, 2022 · 2 comments

Comments

@joerg-walter-de
Copy link

joerg-walter-de commented Dec 12, 2022 •
edited by dhensby
Loading

I am quickly calling an Express handler 100 times. In this handler I do a simple SELECT 1 query against a pool.

Expected behaviour:

A degree of overlap between the queries and the result arrivals

Actual behaviour:

All query responses arrive after all query executions.
Plus: I get a MaxListenersExceededWarning message.

The timing of the queries and result arrivals:

[2022-12-12T15:27:59.451Z] [warn] 2-QUERY 1
[2022-12-12T15:27:59.471Z] [warn] 2-QUERY 2
[2022-12-12T15:27:59.476Z] [warn] 2-QUERY 3
[2022-12-12T15:27:59.481Z] [warn] 2-QUERY 4
[2022-12-12T15:27:59.488Z] [warn] 2-QUERY 5
[2022-12-12T15:27:59.496Z] [warn] 2-QUERY 6
[2022-12-12T15:27:59.500Z] [warn] 2-QUERY 7
[2022-12-12T15:27:59.505Z] [warn] 2-QUERY 8
[2022-12-12T15:27:59.509Z] [warn] 2-QUERY 9
[2022-12-12T15:27:59.513Z] [warn] 2-QUERY 10
[2022-12-12T15:27:59.521Z] [warn] 2-QUERY 11
[2022-12-12T15:27:59.525Z] [warn] 2-QUERY 12
[2022-12-12T15:27:59.530Z] [warn] 2-QUERY 13
[2022-12-12T15:27:59.537Z] [warn] 2-QUERY 14
[2022-12-12T15:27:59.541Z] [warn] 2-QUERY 15
[2022-12-12T15:27:59.545Z] [warn] 2-QUERY 16
[2022-12-12T15:27:59.551Z] [warn] 2-QUERY 17
[2022-12-12T15:27:59.567Z] [warn] 2-QUERY 18
[2022-12-12T15:27:59.572Z] [warn] 2-QUERY 19
[2022-12-12T15:27:59.577Z] [warn] 2-QUERY 20
[2022-12-12T15:27:59.582Z] [warn] 2-QUERY 21
[2022-12-12T15:27:59.587Z] [warn] 2-QUERY 22
[2022-12-12T15:27:59.591Z] [warn] 2-QUERY 23
[2022-12-12T15:27:59.597Z] [warn] 2-QUERY 24
[2022-12-12T15:27:59.601Z] [warn] 2-QUERY 25
[2022-12-12T15:27:59.606Z] [warn] 2-QUERY 26
[2022-12-12T15:27:59.610Z] [warn] 2-QUERY 27
[2022-12-12T15:27:59.615Z] [warn] 2-QUERY 28
[2022-12-12T15:27:59.620Z] [warn] 2-QUERY 29
[2022-12-12T15:27:59.626Z] [warn] 2-QUERY 30
[2022-12-12T15:27:59.631Z] [warn] 2-QUERY 31
[2022-12-12T15:27:59.636Z] [warn] 2-QUERY 32
[2022-12-12T15:27:59.640Z] [warn] 2-QUERY 33
[2022-12-12T15:27:59.645Z] [warn] 2-QUERY 34
[2022-12-12T15:27:59.650Z] [warn] 2-QUERY 35
[2022-12-12T15:27:59.655Z] [warn] 2-QUERY 36
[2022-12-12T15:27:59.660Z] [warn] 2-QUERY 37
[2022-12-12T15:27:59.665Z] [warn] 2-QUERY 38
[2022-12-12T15:27:59.670Z] [warn] 2-QUERY 39
[2022-12-12T15:27:59.675Z] [warn] 2-QUERY 40
[2022-12-12T15:27:59.680Z] [warn] 2-QUERY 41
[2022-12-12T15:27:59.686Z] [warn] 2-QUERY 42
[2022-12-12T15:27:59.691Z] [warn] 2-QUERY 43
[2022-12-12T15:27:59.696Z] [warn] 2-QUERY 44
[2022-12-12T15:27:59.700Z] [warn] 2-QUERY 45
[2022-12-12T15:27:59.705Z] [warn] 2-QUERY 46
[2022-12-12T15:27:59.710Z] [warn] 2-QUERY 47
[2022-12-12T15:27:59.714Z] [warn] 2-QUERY 48
[2022-12-12T15:27:59.720Z] [warn] 2-QUERY 49
[2022-12-12T15:27:59.724Z] [warn] 2-QUERY 50
[2022-12-12T15:27:59.729Z] [warn] 2-QUERY 51
[2022-12-12T15:27:59.734Z] [warn] 2-QUERY 52
[2022-12-12T15:27:59.738Z] [warn] 2-QUERY 53
[2022-12-12T15:27:59.743Z] [warn] 2-QUERY 54
[2022-12-12T15:27:59.749Z] [warn] 2-QUERY 55
[2022-12-12T15:27:59.754Z] [warn] 2-QUERY 56
[2022-12-12T15:27:59.759Z] [warn] 2-QUERY 57
[2022-12-12T15:27:59.763Z] [warn] 2-QUERY 58
[2022-12-12T15:27:59.772Z] [warn] 2-QUERY 59
[2022-12-12T15:27:59.777Z] [warn] 2-QUERY 60
[2022-12-12T15:27:59.782Z] [warn] 2-QUERY 61
[2022-12-12T15:27:59.786Z] [warn] 2-QUERY 62
[2022-12-12T15:27:59.791Z] [warn] 2-QUERY 63
[2022-12-12T15:27:59.797Z] [warn] 2-QUERY 64
[2022-12-12T15:27:59.803Z] [warn] 2-QUERY 65
[2022-12-12T15:27:59.808Z] [warn] 2-QUERY 66
[2022-12-12T15:27:59.813Z] [warn] 2-QUERY 67
[2022-12-12T15:27:59.818Z] [warn] 2-QUERY 68
[2022-12-12T15:27:59.823Z] [warn] 2-QUERY 69
[2022-12-12T15:27:59.828Z] [warn] 2-QUERY 70
[2022-12-12T15:27:59.832Z] [warn] 2-QUERY 71
[2022-12-12T15:27:59.837Z] [warn] 2-QUERY 72
[2022-12-12T15:27:59.842Z] [warn] 2-QUERY 73
[2022-12-12T15:27:59.846Z] [warn] 2-QUERY 74
[2022-12-12T15:27:59.851Z] [warn] 2-QUERY 75
[2022-12-12T15:27:59.856Z] [warn] 2-QUERY 76
[2022-12-12T15:27:59.861Z] [warn] 2-QUERY 77
[2022-12-12T15:27:59.865Z] [warn] 2-QUERY 78
[2022-12-12T15:27:59.870Z] [warn] 2-QUERY 79
[2022-12-12T15:27:59.876Z] [warn] 2-QUERY 80
[2022-12-12T15:27:59.881Z] [warn] 2-QUERY 81
[2022-12-12T15:27:59.886Z] [warn] 2-QUERY 82
[2022-12-12T15:27:59.890Z] [warn] 2-QUERY 83
[2022-12-12T15:27:59.895Z] [warn] 2-QUERY 84
[2022-12-12T15:27:59.900Z] [warn] 2-QUERY 85
[2022-12-12T15:27:59.905Z] [warn] 2-QUERY 86
[2022-12-12T15:27:59.909Z] [warn] 2-QUERY 87
[2022-12-12T15:27:59.914Z] [warn] 2-QUERY 88
[2022-12-12T15:27:59.921Z] [warn] 2-QUERY 89
[2022-12-12T15:27:59.926Z] [warn] 2-QUERY 90
[2022-12-12T15:27:59.930Z] [warn] 2-QUERY 91
[2022-12-12T15:27:59.935Z] [warn] 2-QUERY 92
[2022-12-12T15:27:59.941Z] [warn] 2-QUERY 93
[2022-12-12T15:27:59.946Z] [warn] 2-QUERY 94
[2022-12-12T15:27:59.950Z] [warn] 2-QUERY 95
[2022-12-12T15:27:59.955Z] [warn] 2-QUERY 96
[2022-12-12T15:27:59.960Z] [warn] 2-QUERY 97
[2022-12-12T15:27:59.965Z] [warn] 2-QUERY 98
[2022-12-12T15:27:59.969Z] [warn] 2-QUERY 99
[2022-12-12T15:27:59.974Z] [warn] 2-QUERY 100
[2022-12-12T15:28:00.249Z] [error] 2-SUCCESS 1 took 798.11 ms
[2022-12-12T15:28:00.253Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.260Z] [error] 2-SUCCESS 2 took 789.97 ms
[2022-12-12T15:28:00.263Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.273Z] [error] 2-SUCCESS 3 took 796.6 ms
[2022-12-12T15:28:00.274Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.281Z] [error] 2-SUCCESS 4 took 799.91 ms
[2022-12-12T15:28:00.283Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.315Z] [error] 2-SUCCESS 5 took 826.63 ms
[2022-12-12T15:28:00.317Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.324Z] [error] 2-SUCCESS 6 took 827.97 ms
[2022-12-12T15:28:00.325Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.332Z] [error] 2-SUCCESS 7 took 831.84 ms
[2022-12-12T15:28:00.334Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.354Z] [error] 2-SUCCESS 8 took 848.46 ms
[2022-12-12T15:28:00.356Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.408Z] [error] 2-SUCCESS 9 took 899.46 ms
[2022-12-12T15:28:00.413Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.420Z] [error] 2-SUCCESS 10 took 906.06 ms
[2022-12-12T15:28:00.422Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.428Z] [error] 2-SUCCESS 11 took 907.74 ms
[2022-12-12T15:28:00.430Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.453Z] [error] 2-SUCCESS 12 took 927.78 ms
[2022-12-12T15:28:00.456Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.474Z] [error] 2-SUCCESS 13 took 943.73 ms
[2022-12-12T15:28:00.476Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.483Z] [error] 2-SUCCESS 14 took 946.06 ms
[2022-12-12T15:28:00.485Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.498Z] [error] 2-SUCCESS 15 took 956.83 ms
[2022-12-12T15:28:00.500Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.509Z] [error] 2-SUCCESS 16 took 964.2 ms
[2022-12-12T15:28:00.511Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.517Z] [error] 2-SUCCESS 17 took 965.92 ms
[2022-12-12T15:28:00.519Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.527Z] [error] 2-SUCCESS 18 took 959.8 ms
[2022-12-12T15:28:00.529Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.547Z] [error] 2-SUCCESS 20 took 969.25 ms
[2022-12-12T15:28:00.550Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.556Z] [error] 2-SUCCESS 19 took 984.05 ms
[2022-12-12T15:28:00.558Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.578Z] [error] 2-SUCCESS 21 took 996.43 ms
[2022-12-12T15:28:00.580Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.587Z] [error] 2-SUCCESS 22 took 1000 ms
[2022-12-12T15:28:00.589Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.599Z] [error] 2-SUCCESS 23 took 1008 ms
[2022-12-12T15:28:00.601Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.625Z] [error] 2-SUCCESS 24 took 1028.55 ms
[2022-12-12T15:28:00.629Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.635Z] [error] 2-SUCCESS 25 took 1034.28 ms
[2022-12-12T15:28:00.638Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.644Z] [error] 2-SUCCESS 26 took 1038.62 ms
[2022-12-12T15:28:00.646Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.665Z] [error] 2-SUCCESS 27 took 1054.76 ms
[2022-12-12T15:28:00.667Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.674Z] [error] 2-SUCCESS 28 took 1059.16 ms
[2022-12-12T15:28:00.676Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.696Z] [error] 2-SUCCESS 29 took 1076.05 ms
[2022-12-12T15:28:00.699Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.705Z] [error] 2-SUCCESS 30 took 1079.56 ms
[2022-12-12T15:28:00.707Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.717Z] [error] 2-SUCCESS 31 took 1085.92 ms
[2022-12-12T15:28:00.720Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.734Z] [error] 2-SUCCESS 32 took 1098.43 ms
[2022-12-12T15:28:00.736Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.742Z] [error] 2-SUCCESS 33 took 1101.9 ms
[2022-12-12T15:28:00.745Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.752Z] [error] 2-SUCCESS 34 took 1106.93 ms
[2022-12-12T15:28:00.754Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.773Z] [error] 2-SUCCESS 35 took 1123.43 ms
[2022-12-12T15:28:00.776Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.784Z] [error] 2-SUCCESS 36 took 1128.41 ms
[2022-12-12T15:28:00.785Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.806Z] [error] 2-SUCCESS 37 took 1145.53 ms
[2022-12-12T15:28:00.808Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.815Z] [error] 2-SUCCESS 38 took 1149.68 ms
[2022-12-12T15:28:00.817Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.824Z] [error] 2-SUCCESS 39 took 1153.62 ms
[2022-12-12T15:28:00.825Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.842Z] [error] 2-SUCCESS 40 took 1166.74 ms
[2022-12-12T15:28:00.845Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.851Z] [error] 2-SUCCESS 41 took 1171.14 ms
[2022-12-12T15:28:00.853Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.860Z] [error] 2-SUCCESS 42 took 1173.94 ms
[2022-12-12T15:28:00.862Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.884Z] [error] 2-SUCCESS 43 took 1192.67 ms
[2022-12-12T15:28:00.886Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.892Z] [error] 2-SUCCESS 44 took 1196.27 ms
[2022-12-12T15:28:00.894Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.916Z] [error] 2-SUCCESS 45 took 1215.41 ms
[2022-12-12T15:28:00.918Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.926Z] [error] 2-SUCCESS 46 took 1221.08 ms
[2022-12-12T15:28:00.928Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.940Z] [error] 2-SUCCESS 47 took 1230.74 ms
[2022-12-12T15:28:00.945Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.964Z] [error] 2-SUCCESS 48 took 1249.54 ms
[2022-12-12T15:28:00.966Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.973Z] [error] 2-SUCCESS 49 took 1253.31 ms
[2022-12-12T15:28:00.975Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:00.984Z] [error] 2-SUCCESS 50 took 1259.48 ms
[2022-12-12T15:28:00.986Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:00 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.009Z] [error] 2-SUCCESS 51 took 1280.14 ms
[2022-12-12T15:28:01.011Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.018Z] [error] 2-SUCCESS 52 took 1284.83 ms
[2022-12-12T15:28:01.021Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.046Z] [error] 2-SUCCESS 53 took 1307.97 ms
[2022-12-12T15:28:01.049Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.056Z] [error] 2-SUCCESS 54 took 1313.37 ms
[2022-12-12T15:28:01.060Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.067Z] [error] 2-SUCCESS 55 took 1318.2 ms
[2022-12-12T15:28:01.070Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.091Z] [error] 2-SUCCESS 56 took 1337.63 ms
[2022-12-12T15:28:01.094Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.101Z] [error] 2-SUCCESS 57 took 1342.27 ms
[2022-12-12T15:28:01.103Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.111Z] [error] 2-SUCCESS 58 took 1347.35 ms
[2022-12-12T15:28:01.113Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.141Z] [error] 2-SUCCESS 59 took 1369.19 ms
[2022-12-12T15:28:01.147Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.155Z] [error] 2-SUCCESS 60 took 1378.46 ms
[2022-12-12T15:28:01.157Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.181Z] [error] 2-SUCCESS 61 took 1399.65 ms
[2022-12-12T15:28:01.184Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.191Z] [error] 2-SUCCESS 62 took 1404.47 ms
[2022-12-12T15:28:01.193Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.202Z] [error] 2-SUCCESS 63 took 1410.68 ms
[2022-12-12T15:28:01.204Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.219Z] [error] 2-SUCCESS 64 took 1421.92 ms
[2022-12-12T15:28:01.221Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.235Z] [error] 2-SUCCESS 65 took 1431.89 ms
[2022-12-12T15:28:01.237Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.245Z] [error] 2-SUCCESS 66 took 1436.85 ms
[2022-12-12T15:28:01.247Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.275Z] [error] 2-SUCCESS 67 took 1462.35 ms
[2022-12-12T15:28:01.278Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.292Z] [error] 2-SUCCESS 68 took 1473.6 ms
[2022-12-12T15:28:01.295Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.313Z] [error] 2-SUCCESS 69 took 1490.01 ms
[2022-12-12T15:28:01.315Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.323Z] [error] 2-SUCCESS 70 took 1495.28 ms
[2022-12-12T15:28:01.325Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.334Z] [error] 2-SUCCESS 71 took 1501.41 ms
[2022-12-12T15:28:01.336Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.358Z] [error] 2-SUCCESS 72 took 1520.91 ms
[2022-12-12T15:28:01.361Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.374Z] [error] 2-SUCCESS 73 took 1531.88 ms
[2022-12-12T15:28:01.377Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.384Z] [error] 2-SUCCESS 74 took 1537.91 ms
[2022-12-12T15:28:01.387Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.413Z] [error] 2-SUCCESS 75 took 1562.09 ms
[2022-12-12T15:28:01.416Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.430Z] [error] 2-SUCCESS 76 took 1574 ms
[2022-12-12T15:28:01.432Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.453Z] [error] 2-SUCCESS 78 took 1588.16 ms
[2022-12-12T15:28:01.456Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.464Z] [error] 2-SUCCESS 77 took 1603.5 ms
[2022-12-12T15:28:01.467Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.475Z] [error] 2-SUCCESS 79 took 1605.29 ms
[2022-12-12T15:28:01.477Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.492Z] [error] 2-SUCCESS 80 took 1615.63 ms
[2022-12-12T15:28:01.495Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.510Z] [error] 2-SUCCESS 81 took 1628.8 ms
[2022-12-12T15:28:01.513Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.522Z] [error] 2-SUCCESS 82 took 1635.82 ms
[2022-12-12T15:28:01.525Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.550Z] [error] 2-SUCCESS 83 took 1659.68 ms
[2022-12-12T15:28:01.553Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.573Z] [error] 2-SUCCESS 84 took 1677.8 ms
[2022-12-12T15:28:01.575Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.603Z] [error] 2-SUCCESS 85 took 1703.47 ms
[2022-12-12T15:28:01.608Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.617Z] [error] 2-SUCCESS 86 took 1712.04 ms
[2022-12-12T15:28:01.619Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.628Z] [error] 2-SUCCESS 87 took 1718.72 ms
[2022-12-12T15:28:01.630Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.644Z] [error] 2-SUCCESS 88 took 1729.95 ms
[2022-12-12T15:28:01.647Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.668Z] [error] 2-SUCCESS 89 took 1746.71 ms
[2022-12-12T15:28:01.670Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.678Z] [error] 2-SUCCESS 90 took 1752.41 ms
[2022-12-12T15:28:01.682Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.710Z] [error] 2-SUCCESS 91 took 1779.66 ms
[2022-12-12T15:28:01.712Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.726Z] [error] 2-SUCCESS 92 took 1790.59 ms
[2022-12-12T15:28:01.728Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.744Z] [error] 2-SUCCESS 93 took 1803.09 ms
[2022-12-12T15:28:01.746Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.751Z] [error] 2-SUCCESS 94 took 1805.33 ms
[2022-12-12T15:28:01.753Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.758Z] [error] 2-SUCCESS 95 took 1807.48 ms
[2022-12-12T15:28:01.760Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.773Z] [error] 2-SUCCESS 96 took 1818.01 ms
[2022-12-12T15:28:01.776Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.789Z] [error] 2-SUCCESS 97 took 1829.41 ms
[2022-12-12T15:28:01.792Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.800Z] [error] 2-SUCCESS 98 took 1834.99 ms
[2022-12-12T15:28:01.802Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.813Z] [error] 2-SUCCESS 99 took 1843.85 ms
[2022-12-12T15:28:01.819Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
[2022-12-12T15:28:01.824Z] [error] 2-SUCCESS 100 took 1849.99 ms
[2022-12-12T15:28:01.826Z] [info] ::ffff:127.0.0.1 - - [12/Dec/2022:15:28:01 +0000] "GET /v1/query-test-2 HTTP/1.1" 201 - "-" "httpyac"
(node:14800) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 abort listeners added to [EventEmitter]. Use emitter.setMaxListeners() to increase limit
(Use `node --trace-warnings ...` to show where the warning was created)
(node:14800) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 abort listeners added to [EventEmitter]. Use emitter.setMaxListeners() to increase limit
(node:14800) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 abort listeners added to [EventEmitter]. Use emitter.setMaxListeners() to increase limit

Configuration:

My code:

const poolConfiguration: MsSql.config = {
    user: Configuration.getString('SQL_DB_CONNECTION_USER'),
    password: Configuration.getString('SQL_DB_CONNECTION_PASSWORD'),
    server: Configuration.getString('SQL_DB_CONNECTION_SERVER'),
    database: Configuration.getString('SQL_DB_CONNECTION_DATABASE'),
    parseJSON: true,
    driver: 'tedious',
    options: {
        encrypt: true
    },
    pool: {
        max: 8,
        min: 2
    }
};

let pool = new MsSql.ConnectionPool(poolConfiguration);
let x=0;
pool.connect().then( () => {
    Logger().debug(`[pool] Creating SQL Server pool connection...DONE`);
    return pool;
}).catch(error => {
    Logger().error(
        `[pool] Creating SQL Server pool connection...FAILED: ${JSON.stringify(error)}.`);
    return pool;
});

function queryTest2(request: Request, response: Response): Promise<any>
{
    if(!pool.connected)
    {
        response.status(404).send();
        return Promise.resolve(true);
    }
    const start = hrtime.bigint();
     x=x+1;
     const myId = x;
    Logger().warn(`2-QUERY ${myId}`);

     return pool.query('select 1').then(result => {
        const end = hrtime.bigint();
        Logger().error(`2-SUCCESS ${myId} took ${Number((end-start) * 100n / 1000000n) / 100} ms`);
        return response.status(201).send();
     });
 }

Software versions

  • NodeJS: 16.15.1
  • node-mssql: 9.0.1
  • SQL Server: 10.0.2000.8, Azure SQL Server, Standard S1: 20 DTUs,
@dhensby
Copy link
Collaborator

dhensby commented Dec 14, 2022 •
edited
Loading

I'm a bit unsure what I can provide here. How are you running your 100 requests against express? Node is single threaded, so it doesn't seem completely unreasonable that this may be handled like this.

If you add some kind of setTimeout in each request handler (and some random wait time), then you'll likely start to see some variability in responses.

If you only have a maximum pool size of 8, you're very likely to see a linear progression like this.

I imagine what is going on is something like:

  • A request comes in, it is handled, a request to the DB server is dispatched (meanwhile other requests are coming in/being queued)
  • next request is handled, a request is dispatched to the DB...
  • repeat for next 6 requests (making 8 requests in total)
  • another request comes in, the pool is depleted so the query is queued... repeat
  • whilst this happens, some db queries are fulfilled and need to be picked up by the event loop
  • node resolves all the elements in the event loop (incoming requests)
  • Other queries queued
  • response streams initialised / started / etc.
  • then all responses are sent out

Part of this is going to be limited by how many open sockets node can have at a time too, possibly. You'll need to do some pretty deep debugging to truly understand what is going on, but if the requests are also triggered in the same node thread, this linear queueing is going to be even more expected.

@dhensby
Copy link
Collaborator

dhensby commented Dec 24, 2022

I'll close this as I've not received a response

@dhensby dhensby closed this as completed Dec 24, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@dhensby @joerg-walter-de