cbc-cat timing gives wildy fluctuating times for the same document, shows two requests for every document

See also https://issues.couchbase.com/browse/CCBC-1210

Customer uses cbc-cat to investigate time to get a document.

 

cbc cat  -T -u Administrator -P password -U couchbase://localhost/travel-sample  airport_1254 2>&1 | grep '#'

[110  - 119 ]us |######################################## - 1

[230  - 239 ]us |######################################## - 1

The first thing to notice is that there are two measurements to retrieve a single document.  Some debugging has shown that the first request is PROTOCOL_BINARY_CMD_COLLECTIONS_GET_CID.  At first glance at the histogram, one might think that getting a single document takes 239 micro-seconds or less, while it actually takes the sum of those two requests. 

cbc cat  -T -u Administrator -P password -U couchbase://localhost/travel-sample  airport_1254 airport_1254 2>&1 | grep '#'

[120  - 129 ]us |######################################## - 1

[160  - 169 ]us |######################################## - 1

[290  - 299 ]us |######################################## - 1

[320  - 329 ]us |######################################## - 1

When more 'gets' are done in a single cbc-cat command, the response times get slower.  This is because the requests are issued in parallel.  Some take almost 5 times as long as when a single document is retrieved (below)

cbc cat  -T -u Administrator -P password -U couchbase://localhost/travel-sample  airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254   2>&1 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254  | grep '#'

[290  - 299 ]us |################ - 2

[320  - 329 ]us |######## - 1

[330  - 339 ]us |######## - 1

[340  - 349 ]us |################################ - 4

[350  - 359 ]us |######################## - 3

[360  - 369 ]us |######################################## - 5

[370  - 379 ]us |################################ - 4

[390  - 399 ]us |######## - 1

[410  - 419 ]us |######## - 1

[420  - 429 ]us |######## - 1

[430  - 439 ]us |######## - 1

[440  - 449 ]us |######## - 1

[450  - 459 ]us |######## - 1

[460  - 469 ]us |######## - 1

[470  - 479 ]us |######## - 1

[480  - 489 ]us |######## - 1

[490  - 499 ]us |######## - 1

[500  - 509 ]us |######## - 1

[510  - 519 ]us |######## - 1

If we modify cbc-cat adding a  --serial option that processes each get serially, the timing looks much better. Also, there is only one PROTOCOL_BINARY_CMD_COLLECTIONS_GET_CID request. 

cbc cat  -T -u Administrator -P password -U couchbase://localhost/travel-sample  airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254   2>&1 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254 airport_1254  --serial | grep '#'

[50   - 59  ]us |######################################## - 7

[60   - 69  ]us |##### - 1

[70   - 79  ]us |###################### - 4

[80   - 89  ]us |################# - 3

[110  - 119 ]us |##### - 1

[170  - 179 ]us |##### - 1