[MB-60276] STAT Operation Delays Causing Worker Thread Blocking in Memcached (7.2.0+)

Product: Couchbase Server
Component: data-service
Issue Link: MB-60276
Affects Version(s): 7.2.4
Fix Version(s): 7.2.5, 7.6.0, 8.0.0

Summary

• When a client connects to data service (memcached), it is assigned a worker thread to handle its operations.
• If STAT operations become unexpectedly slow, they block the worker thread, delaying all other connections handled by that thread.
• This issue only affects version 7.2.0 and above.

Symptoms

• Clients see slow KV operations
• Slow operations for STAT calls in memcached.log
• Node(s) with the Data Service marked as not ready

Triggers

• The issue occurs when all STAT operations are slow for any reason

Verification

• This issue only affects clusters with couchstore buckets. The resulting slow operations can be present on any type of bucket
• Slow STAT operations with keylen: 0 in memcached.log
• Slow stat:all in stats.log or in the output of cbstats stat-timings

Example of slow STAT operation:

2024-04-17T19:05:51.984830+02:00 WARNING 516: Slow operation: {"bucket":"persistdb","cid":"127.0.0.1:58334/0","command":"STAT","duration":"615 ms","packet":{"bodylen":0,"cas":0,"datatype":"raw","extlen":0,"key":"<ud></ud>","keylen":0,"magic":"ClientRequest","opaque":0,"opcode":"STAT","vbucket":0},"peer":{"ip":"127.0.0.1","port":58334},"trace":"r

You can use the following command to check if the relevant slow operations are present in memcached.log files

rg -i "slow operation.*STAT" */memcached.log | rg '"keylen":0' -c
443

If they are, you can correlate the times of the slow operations with the observed latencies/not ready:

rg -i "slow operation.*STAT" */memcached.log | rg '"keylen":0' | rg -o "\d{4}-\d\d-\d\dT\d\d" | sort | uniq -c
   5 2024-04-17T13
 111 2024-04-17T14
  50 2024-04-17T15
  29 2024-04-17T16
 112 2024-04-17T17
 117 2024-04-17T18
  19 2024-04-17T19

If there are no such slow operations, it is still possible that there were slow all STAT operations that were below the slow operation threshold (default: 500ms).

Therefore, we need to also check the general timings of the all STAT operation. Due to another issue ( MB-61466 Closed ), these may not be present in cbcollect_info logs on some versions (anything prior to 7.6).

If it is present, you can find it by looking for stat:all in stats.log file. If not, then run a cbstats stat-timings on all nodes with the Data Service.

Example commands:

/opt/couchbase/bin/cbstats -u username -S -a localhost stat-timings

Example output that is NOT seeing this issue:

stat:all (43204 total)
       0us - 1215us : (  0.0185%)     8  
    1215us - 2687us : ( 41.4638%) 17906 ████████████████▏
    2687us - 2687us : ( 41.4638%)     0  
    2687us - 2815us : ( 97.1253%) 24048 █████████████████████▋
    2815us - 2815us : ( 97.1253%)     0  
    2815us - 2943us : ( 99.8935%)  1196 █ 
    2943us - 2943us : ( 99.8935%)     0  
    2943us - 3071us : ( 99.9352%)    18  
    3071us - 3071us : ( 99.9352%)     0  
    3071us - 3199us : ( 99.9745%)    17  
    3199us - 3199us : ( 99.9745%)     0  
    3199us - 3327us : ( 99.9838%)     4  
    3327us - 3327us : ( 99.9838%)     0  
    3327us - 3455us : ( 99.9861%)     1  
    3455us - 3711us : ( 99.9884%)     1  
    3711us - 6911us : ( 99.9907%)     1  
    6911us - 6911us : ( 99.9907%)     0  
    6911us -   10ms : ( 99.9931%)     1  
      10ms -   10ms : ( 99.9931%)     0  
      10ms -   14ms : ( 99.9954%)     1  
      14ms -   14ms : ( 99.9954%)     0  
      14ms -   28ms : ( 99.9977%)     1  
      28ms -   28ms : ( 99.9977%)     0  
      28ms -   45ms : (100.0000%)     1

From this output, we can see that there was a small number of times where the all STAT operation could have caused a slight less than 50ms delay to other operations.

Workarounds

• Remove all couchstore type buckets
• upgrade to a version containing the fix.