Details
Description
In the output from http://perf.jenkins.couchbase.com/view/Eventing/job/themis/9426/console the following slow stat operations was seen
cbcollect_info_ns_1@172.23.96.17_20210318-214647/memcached.log:2021-03-18T13:52:05.609557-07:00 WARNING 146: Slow operation. {"cid":"127.0.0.1:47635/0","duration":"1983 ms","trace":"request=2466646701127492:1983136 execute=2466646701127492:1983136","command":"STAT","peer":"{"ip":"127.0.0.1","port":47635}","bucket":"bucket-1","packet":{"bodylen":0,"cas":0,"datatype":"raw","extlen":0,"key":"<ud></ud>","keylen":0,"magic":"ClientRequest","opaque":0,"opcode":"STAT","vbucket":0}}
|
cbcollect_info_ns_1@172.23.96.17_20210318-214647/memcached.log:2021-03-18T13:54:16.555175-07:00 WARNING 284: Slow operation. {"cid":"127.0.0.1:47200/0","duration":"1123 ms","trace":"request=2466778509361025:1122805 execute=2466778509361025:1122805","command":"STAT","peer":"{"ip":"127.0.0.1","port":47200}","bucket":"eventing-bucket-1","packet":{"bodylen":0,"cas":0,"datatype":"raw","extlen":0,"key":"<ud></ud>","keylen":0,"magic":"ClientRequest","opaque":0,"opcode":"STAT","vbucket":0}}
|
On that node:
The following data is collected for "STAT"
|
[ 0.00 - 5.00]us (0.0000%) 19|
|
[ 5.00 - 55.00]us (10.0000%) 2854| ##################################
|
[ 55.00 - 63.00]us (20.0000%) 2966| ###################################
|
[ 63.00 - 71.00]us (30.0000%) 3667| ############################################
|
[ 71.00 - 75.00]us (40.0000%) 1335| ################
|
[ 75.00 - 87.00]us (50.0000%) 2545| ##############################
|
[ 87.00 - 95.00]us (55.0000%) 1402| ################
|
[ 95.00 - 103.00]us (60.0000%) 1624| ###################
|
[103.00 - 111.00]us (65.0000%) 1236| ##############
|
[111.00 - 119.00]us (70.0000%) 1155| #############
|
[119.00 - 159.00]us (75.0000%) 1224| ##############
|
[159.00 - 207.00]us (77.5000%) 726| ########
|
[207.00 - 247.00]us (80.0000%) 572| ######
|
[247.00 - 383.00]us (82.5000%) 764| #########
|
[383.00 - 511.00]us (85.0000%) 529| ######
|
[ 0.51 - 1.22]ms (87.5000%) 929| ###########
|
[ 1.22 - 1.28]ms (88.7500%) 290| ###
|
[ 1.28 - 1.34]ms (90.0000%) 213| ##
|
[ 1.34 - 1.47]ms (91.2500%) 253| ###
|
[ 1.47 - 1.86]ms (92.5000%) 403| ####
|
[ 1.86 - 2.05]ms (93.7500%) 339| ####
|
[ 2.05 - 2.17]ms (94.3750%) 222| ##
|
[ 2.17 - 2.30]ms (95.0000%) 173| ##
|
[ 2.30 - 2.43]ms (95.6250%) 341| ####
|
[ 2.43 - 2.43]ms (96.2500%) 0|
|
[ 2.43 - 2.43]ms (96.8750%) 0|
|
[ 2.43 - 2.56]ms (97.1875%) 262| ###
|
[ 2.56 - 2.56]ms (97.5000%) 0|
|
[ 2.56 - 2.56]ms (97.8125%) 0|
|
[ 2.56 - 2.69]ms (98.1250%) 74|
|
[ 2.69 - 2.82]ms (98.4375%) 87| #
|
[ 2.82 - 2.94]ms (98.5938%) 118| #
|
[ 2.94 - 2.94]ms (98.7500%) 0|
|
[ 2.94 - 2.94]ms (98.9062%) 0|
|
[ 2.94 - 3.07]ms (99.0625%) 100| #
|
[ 3.07 - 3.07]ms (99.2188%) 0|
|
[ 3.07 - 3.07]ms (99.2969%) 0|
|
[ 3.07 - 3.20]ms (99.3750%) 56|
|
[ 3.20 - 3.20]ms (99.4531%) 0|
|
[ 3.20 - 3.33]ms (99.5312%) 10|
|
[ 3.33 - 3.97]ms (99.6094%) 21|
|
[ 3.97 - 4.35]ms (99.6484%) 10|
|
[ 4.35 - 5.89]ms (99.6875%) 7|
|
[ 5.89 - 13.82]ms (99.7266%) 11|
|
[ 13.82 - 25.60]ms (99.7656%) 10|
|
[ 25.60 - 43.01]ms (99.8047%) 11|
|
[ 43.01 - 53.25]ms (99.8242%) 5|
|
[ 53.25 - 59.39]ms (99.8438%) 6|
|
[ 59.39 - 65.54]ms (99.8633%) 4|
|
[ 65.54 - 73.73]ms (99.8828%) 6|
|
[ 73.73 - 81.92]ms (99.9023%) 6|
|
[ 81.92 - 86.01]ms (99.9121%) 3|
|
[ 86.01 - 90.11]ms (99.9219%) 1|
|
[ 90.11 - 98.30]ms (99.9316%) 2|
|
[ 98.30 - 106.50]ms (99.9414%) 5|
|
[106.50 - 110.59]ms (99.9512%) 1|
|
[110.59 - 114.69]ms (99.9561%) 2|
|
[114.69 - 114.69]ms (99.9609%) 0|
|
[114.69 - 122.88]ms (99.9658%) 2|
|
[122.88 - 126.97]ms (99.9707%) 1|
|
[126.97 - 139.26]ms (99.9756%) 2|
|
[139.26 - 139.26]ms (99.9780%) 0|
|
[139.26 - 139.26]ms (99.9805%) 0|
|
[139.26 - 147.46]ms (99.9829%) 1|
|
[147.46 - 196.61]ms (99.9854%) 1|
|
[196.61 - 196.61]ms (99.9878%) 0|
|
[196.61 - 786.43]ms (99.9890%) 1|
|
[786.43 - 786.43]ms (99.9902%) 0|
|
[786.43 - 786.43]ms (99.9915%) 0|
|
[ 0.79 - 1.18]s (99.9927%) 1|
|
[ 1.18 - 1.18]s (99.9939%) 0|
|
[ 1.18 - 1.18]s (99.9945%) 0|
|
[ 1.18 - 1.18]s (99.9951%) 0|
|
[ 1.18 - 1.18]s (99.9957%) 0|
|
[ 1.18 - 2.03]s (99.9963%) 1|
|
[ 2.03 - 2.03]s (100.0000%) 0|
|
Total: 26609 operations
|
We should figure out why we see those really really slow stat ops
Attachments
For Gerrit Dashboard: MB-45083 | ||||||
---|---|---|---|---|---|---|
# | Subject | Branch | Project | Status | CR | V |
149033,2 | MB-45083: Remove stats_mutex | master | kv_engine | Status: MERGED | +2 | +1 |