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
>
>
