Willy, Thank you so much for your response. We are not running in a VM, although our backend DB does, but I can't see how that would be relevant. This is a basic haproxy install via apt on ubuntu. I parsed the log myself to make it easier to read, but I realize I didn't include some important fields. Below are the entries without any fields removed and some modified for privacy. I've also included our log-format config.
Thanks again for your input. Dave log-format [%t]\ %ID\ ac=%ac\ fc=%fc\ bc=%bc\ bq=%bq\ sc=%sc\ sq=%sq\ rc=%rc\ Tq=%Tq\ Tw=%Tw\ Tc=%Tc\ Tr=%Tr\ Tt=%Tt\ tsc=%tsc\ cip=%ci:%cp\ req=%{+Q}r\ ST=%ST\ H=%H\ bs=%b:%s\ hdrs="%hr"\ v=3\ reqB=%U\ resB=%B Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9268_0A954CD4:01BB_55F1E13D_61AF:2AB0 ac=2266 fc=2265 bc=1058 bq=0 sc=383 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37480 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-04 hdrs="{query_1}" v=3 reqB=834 resB=241 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9269_0A954CD4:01BB_55F1E13D_61B0:2AB0 ac=2266 fc=2265 bc=1057 bq=0 sc=303 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37481 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-02 hdrs="{query_2}" v=3 reqB=910 resB=249 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:926A_0A954CD4:01BB_55F1E13D_61B1:2AB0 ac=2266 fc=2265 bc=1056 bq=0 sc=311 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37482 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-03 hdrs="{query_3}" v=3 reqB=963 resB=247 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:926C_0A954CD4:01BB_55F1E13D_61B2:2AB0 ac=2266 fc=2265 bc=1055 bq=0 sc=382 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37484 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-04 hdrs="{query_4}" v=3 reqB=1372 resB=304 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:926B_0A954CD4:01BB_55F1E13D_61B3:2AB0 ac=2266 fc=2265 bc=1054 bq=0 sc=302 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37483 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-02 hdrs="{query_5}" v=3 reqB=1229 resB=291 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:926D_0A954CD4:01BB_55F1E13D_61B4:2AB0 ac=2266 fc=2265 bc=1053 bq=0 sc=310 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37485 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-03 hdrs="{query_6}" v=3 reqB=1402 resB=314 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:926E_0A954CD4:01BB_55F1E13D_61B5:2AB0 ac=2266 fc=2265 bc=1052 bq=0 sc=62 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37486 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-05 hdrs="{query_7}" v=3 reqB=1419 resB=292 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36CDCE43:9270_0A954CD4:01BB_55F1E13D_61B6:2AB0 ac=2266 fc=2265 bc=1051 bq=0 sc=309 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 3.3.3.3:37488 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-03 hdrs="{query_8}" v=3 reqB=935 resB=274 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:926F_0A954CD4:01BB_55F1E13D_61B7:2AB0 ac=2266 fc=2265 bc=383 bq=0 sc=384 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37487 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=626 resB=1928 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9270_0A954CD4:01BB_55F1E13D_61B8:2AB0 ac=2266 fc=2265 bc=1050 bq=0 sc=381 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37488 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-04 hdrs="{query_10}" v=3 reqB=669 resB=352 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9271_0A954CD4:01BB_55F1E13D_61B9:2AB0 ac=2266 fc=2265 bc=1049 bq=0 sc=301 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37489 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-02 hdrs="{query_11}" v=3 reqB=1879 resB=413 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9272_0A954CD4:01BB_55F1E13D_61BA:2AB0 ac=2266 fc=2265 bc=1048 bq=0 sc=308 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37490 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-03 hdrs="{query_12}" v=3 reqB=1899 resB=413 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9273_0A954CD4:01BB_55F1E13D_61BB:2AB0 ac=2266 fc=2265 bc=382 bq=0 sc=383 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37491 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=627 resB=1601 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9274_0A954CD4:01BB_55F1E13D_61BC:2AB0 ac=2266 fc=2265 bc=1047 bq=0 sc=380 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37492 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-04 hdrs="{query_13}" v=3 reqB=688 resB=229 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36A1D587:D2C6_0A954CD4:01BB_55F1E13D_61BD:2AB0 ac=2266 fc=2265 bc=1046 bq=0 sc=300 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 2.2.2.2:53958 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-02 hdrs="{query_10}" v=3 reqB=670 resB=226 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36A1D587:D2C7_0A954CD4:01BB_55F1E13D_61BE:2AB0 ac=2266 fc=2265 bc=1045 bq=0 sc=307 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 2.2.2.2:53959 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-03 hdrs="{query_11}" v=3 reqB=1880 resB=413 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36A1D587:D2C8_0A954CD4:01BB_55F1E13D_61BF:2AB0 ac=2266 fc=2265 bc=1044 bq=0 sc=379 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 2.2.2.2:53960 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-04 hdrs="{query_12}" v=3 reqB=1900 resB=413 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36CDCE43:9271_0A954CD4:01BB_55F1E13D_61C0:2AB0 ac=2266 fc=2265 bc=381 bq=0 sc=382 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 3.3.3.3:37489 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=627 resB=2225 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9275_0A954CD4:01BB_55F1E13D_61C1:2AB0 ac=2266 fc=2265 bc=380 bq=0 sc=381 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37493 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=626 resB=1680 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36A1D587:D2C9_0A954CD4:01BB_55F1E13D_61C2:2AB0 ac=2266 fc=2265 bc=379 bq=0 sc=380 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 2.2.2.2:53961 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=627 resB=1752 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36CDCE43:9272_0A954CD4:01BB_55F1E13D_61C3:2AB0 ac=2266 fc=2265 bc=378 bq=0 sc=379 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 3.3.3.3:37490 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=627 resB=1243 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36A1D587:D2CA_0A954CD4:01BB_55F1E13D_61C4:2AB0 ac=2266 fc=2265 bc=377 bq=0 sc=378 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 2.2.2.2:53962 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_14}" v=3 reqB=629 resB=1220 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36CDCE43:9273_0A954CD4:01BB_55F1E13D_61C5:2AB0 ac=2266 fc=2265 bc=376 bq=0 sc=377 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 3.3.3.3:37491 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=625 resB=1799 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36A1D587:D2CB_0A954CD4:01BB_55F1E13D_61C6:2AB0 ac=2266 fc=2265 bc=375 bq=0 sc=376 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 2.2.2.2:53963 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=627 resB=1998 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9277_0A954CD4:01BB_55F1E13D_61C7:2AB0 ac=2266 fc=2265 bc=374 bq=0 sc=375 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37495 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=627 resB=1568 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36A1D587:D2CC_0A954CD4:01BB_55F1E13D_61C8:2AB0 ac=2266 fc=2265 bc=373 bq=0 sc=374 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 2.2.2.2:53964 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=627 resB=2183 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36A1D587:D2CD_0A954CD4:01BB_55F1E13D_61C9:2AB0 ac=2266 fc=2265 bc=1043 bq=0 sc=299 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 2.2.2.2:53965 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-02 hdrs="{query_13}" v=3 reqB=685 resB=229 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:9278_0A954CD4:01BB_55F1E13D_61CA:2AB0 ac=2266 fc=2265 bc=372 bq=0 sc=373 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37496 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_9}" v=3 reqB=627 resB=1440 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:927A_0A954CD4:01BB_55F1E13D_61CC:2AB0 ac=2266 fc=2265 bc=1042 bq=0 sc=378 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37498 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-04 hdrs="{query_15}" v=3 reqB=2227 resB=421 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36CDCE43:9274_0A954CD4:01BB_55F1E13D_61CD:2AB0 ac=2266 fc=2265 bc=1041 bq=0 sc=298 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 3.3.3.3:37492 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-02 hdrs="{query_14}" v=3 reqB=627 resB=1841 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 3690005E:927B_0A954CD4:01BB_55F1E13D_61CE:2AB0 ac=2266 fc=2265 bc=371 bq=0 sc=372 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 1.1.1.1:37499 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_write:production-01 hdrs="{query_13}" v=3 reqB=688 resB=1496 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36CDCE43:9275_0A954CD4:01BB_55F1E13D_61CF:2AB0 ac=2266 fc=2265 bc=1040 bq=0 sc=306 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 3.3.3.3:37493 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-03 hdrs="{query_10}" v=3 reqB=670 resB=352 Sep 10 20:00:00 <hidden> haproxy[10928]: [10/Sep/2015:19:59:57.070] 36CDCE43:9277_0A954CD4:01BB_55F1E13D_61D1:2AB0 ac=2266 fc=2265 bc=1039 bq=0 sc=297 sq=0 rc=0 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 tsc=---- cip= 3.3.3.3:37495 req="POST /path/hidden HTTP/1.1" ST=200 H=<hidden> bs=db_production_read:production-02 hdrs="{query_12}" v=3 reqB=1900 resB=413 DAVE STERN ENGINEERING FIFTYTHREE, INC. <http://www.fiftythree.com/> 60 HUDSON ST #1810 NEW YORK, NY 10013 <http://goo.gl/Rzk6lZ> @DAVESTERN1 <https://twitter.com/davestern1> On Mon, Sep 14, 2015 at 1:33 AM, Willy Tarreau <w...@1wt.eu> wrote: > Hello Dave, > > On Fri, Sep 11, 2015 at 04:36:44PM -0400, Dave Stern wrote: > > We run haproxy 1.5.14 on Ubuntu 14.04 in AWS. It load balances > connections > > from heroku to our backend, a neo4j cluster of multiple instances. It > also > > terminates SSL and handles auth. Connections to the backend are over > > private network space within our AWS network and via unencrypted http. > > > > During a recent event with heavy load, we saw log entries with the same > > repeating pattern of multiple lines with the exact same Tq, Tc, Tr and Tt > > values, but with different requests from different clients routed to > > different backend pool members. We're not sure what's causing this or if > it > > relates to performance issues we saw during our events. Here's some log > > lines with excerpted fields. We send a custom header with the query name > > for metrics, which I've replaced with generic entries. I also replaced > the > > real client IP with 1.1.1.1, 2.2.2.2, etc. > > > > > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37480 > > bs=db_production_read:production-04 hdrs="{query_1}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37481 > > bs=db_production_read:production-02 hdrs="{query_2}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37482 > > bs=db_production_read:production-03 hdrs="{query_3}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37484 > > bs=db_production_read:production-04 hdrs="{query_4}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37483 > > bs=db_production_read:production-02 hdrs="{query_5}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37485 > > bs=db_production_read:production-03 hdrs="{query_6}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37486 > > bs=db_production_read:production-05 hdrs="{query_7}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=2.2.2.2:37488 > > bs=db_production_read:production-03 hdrs="{query_8}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37487 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37488 > > bs=db_production_read:production-04 hdrs="{query_10}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37489 > > bs=db_production_read:production-02 hdrs="{query_11}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37490 > > bs=db_production_read:production-03 hdrs="{query_12}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37491 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37492 > > bs=db_production_read:production-04 hdrs="{query_13}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=3.3.3.3:53958 > > bs=db_production_read:production-02 hdrs="{query_10}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=3.3.3.3:53959 > > bs=db_production_read:production-03 hdrs="{query_11}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=3.3.3.3:53960 > > bs=db_production_read:production-04 hdrs="{query_12}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=2.2.2.2:37489 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37493 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=3.3.3.3:53961 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=2.2.2.2:37490 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=3.3.3.3:53962 > > bs=db_production_write:production-01 hdrs="{query_14}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=2.2.2.2:37491 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=3.3.3.3:53963 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37495 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=3.3.3.3:53964 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=3.3.3.3:53965 > > bs=db_production_read:production-02 hdrs="{query_13}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37496 > > bs=db_production_write:production-01 hdrs="{query_9}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37498 > > bs=db_production_read:production-04 hdrs="{query_15}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=2.2.2.2:37492 > > bs=db_production_read:production-02 hdrs="{query_14}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=1.1.1.1:37499 > > bs=db_production_write:production-01 hdrs="{query_13}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=2.2.2.2:37493 > > bs=db_production_read:production-03 hdrs="{query_10}" > > Sep 10 20:00:00 Tq=1060 Tw=0 Tc=1204 Tr=922 Tt=3186 cip=2.2.2.2:37495 > > bs=db_production_read:production-02 hdrs="{query_12}" > > > > The logs repeat like this with different sets of entries with the same > Tq, > > Tc, Tr and Tt for all lines. Is this a known phenomena? > > I don't see a problem here, but unfortunately you're missing important > information in your logs, such as the position in the queue. Here > what happened is that you received many requests at once and the > server did not respond for some time (maybe it was stuck doing some > heavy work) and suddenly it released some room and all pending > requests could be processed. > > To be honnest I find it surprizing that the connect time is the same > for all of them for all requests, and even more that the response time > is the same. I would have understood it from a very small time but here > we're almost at one second so such long response times generally tend > to be distributed more widely. > > > A bug in the logging or code? > > I don't believe in this because other fields differ (eg: source address > and port) and the log lines are built from scratch for all requests, using > information picked in the session itself. > > > Some kind of connection reuse we're not aware of? > > No, as you can see the sources (address, port) differ. > > There could be another option : maybe you're running in a VM with a broken > clock jumping back and forth (as in many VMs) and the time you're seeing > is the result of time correction because you have only a few discrete, > valid > time events : > - the time all connections were accepted > - the time all connections got dequeued > - the time all of them managed to connect > - the time all responses were received > > For example if all events spanned over 1 second and you had only 5 > different > clock values within this second, you'll get all similar values everywhere > as > long as events differ by less than the difference between them (eg: 200ms). > > Hoping this helps, > Willy > >