15.6.2.8. memcached Logs

Output when using -v

The lowest verbosity level shows you:

Examples of the error messages output at this level include:

<%d send buffer was %d, now %dCan't listen for events on fd %dCan't read from libevent pipeCatastrophic: event fd doesn't match conn fd!Couldn't build responseCouldn't realloc input bufferCouldn't update eventFailed to build UDP headersFailed to read, and not due to blockingToo many open connectionsUnexpected state %d

Output when using -vv

When using the second level of verbosity, you get more detailed information about protocol operations, keys updated, chunk and network operatings and details.

During the initial start-up of memcached with this level of verbosity, you are shown the sizes of the individual slab classes, the chunk sizes, and the number of entries per slab. These do not show the allocation of the slabs, just the slabs that would be created when data is added. You are also given information about the listen queues and buffers used to send information. A sample of the output generated for a TCP/IP based system with the default memory and growth factors is given below:

shell> memcached -vvslab class   1: chunk size     80 perslab 13107slab class   2: chunk size    104 perslab 10082slab class   3: chunk size    136 perslab  7710slab class   4: chunk size    176 perslab  5957slab class   5: chunk size    224 perslab  4681slab class   6: chunk size    280 perslab  3744slab class   7: chunk size    352 perslab  2978slab class   8: chunk size    440 perslab  2383slab class   9: chunk size    552 perslab  1899slab class  10: chunk size    696 perslab  1506slab class  11: chunk size    872 perslab  1202slab class  12: chunk size   1096 perslab   956slab class  13: chunk size   1376 perslab   762slab class  14: chunk size   1720 perslab   609slab class  15: chunk size   2152 perslab   487slab class  16: chunk size   2696 perslab   388slab class  17: chunk size   3376 perslab   310slab class  18: chunk size   4224 perslab   248slab class  19: chunk size   5280 perslab   198slab class  20: chunk size   6600 perslab   158slab class  21: chunk size   8256 perslab   127slab class  22: chunk size  10320 perslab   101slab class  23: chunk size  12904 perslab    81slab class  24: chunk size  16136 perslab    64slab class  25: chunk size  20176 perslab    51slab class  26: chunk size  25224 perslab    41slab class  27: chunk size  31536 perslab    33slab class  28: chunk size  39424 perslab    26slab class  29: chunk size  49280 perslab    21slab class  30: chunk size  61600 perslab    17slab class  31: chunk size  77000 perslab    13slab class  32: chunk size  96256 perslab    10slab class  33: chunk size 120320 perslab     8slab class  34: chunk size 150400 perslab     6slab class  35: chunk size 188000 perslab     5slab class  36: chunk size 235000 perslab     4slab class  37: chunk size 293752 perslab     3slab class  38: chunk size 367192 perslab     2slab class  39: chunk size 458992 perslab     2<26 server listening (auto-negotiate)<29 server listening (auto-negotiate)<30 send buffer was 57344, now 2097152<31 send buffer was 57344, now 2097152<30 server listening (udp)<30 server listening (udp)<31 server listening (udp)<30 server listening (udp)<30 server listening (udp)<31 server listening (udp)<31 server listening (udp)<31 server listening (udp)

Using this verbosity level can be a useful way to check the effects of the growth factor used on slabs with different memory allocations, which in turn can be used to better tune the growth factor to suit the data you are storing in the cache. For example, if you set the growth factor to 4 (quadrupling the size of each slab):

shell> memcached -f 4 -m 1g -vvslab class   1: chunk size     80 perslab 13107slab class   2: chunk size    320 perslab  3276slab class   3: chunk size   1280 perslab   819slab class   4: chunk size   5120 perslab   204slab class   5: chunk size  20480 perslab    51slab class   6: chunk size  81920 perslab    12slab class   7: chunk size 327680 perslab     3...

During use of the cache, this verbosity level also prints out detailed information on the storage and recovery of keys and other information. An example of the output during a typical set/get and increment/decrement operation is shown below.

32: Client using the ascii protocol<32 set my_key 0 0 10>32 STORED<32 set object_key 1 0 36>32 STORED<32 get my_key >32 sending key my_key>32 END<32 get object_key >32 sending key object_key>32 END<32 set key 0 0 6>32 STORED<32 incr key 1>32 789544<32 decr key 1>32 789543<32 incr key 2>32 789545<32 set my_key 0 0 10>32 STORED<32 set object_key 1 0 36>32 STORED<32 get my_key >32 sending key my_key>32 END<32 get object_key >32 sending key object_key1 1 36>32 END<32 set key 0 0 6>32 STORED<32 incr key 1>32 789544<32 decr key 1>32 789543<32 incr key 2>32 789545

During client communication, for each line, the initial character shows the direction of flow of the information. The < for communication from the client to the memcached server and > for communication back to the client. The number is the numeric socket descriptor for the connection.

Output when using -vvv

This level of verbosity includes the transitions of connections between different states in the event library while reading and writing content to/from the clients. It should be used to diagnose and identify issues in client communication. For example, you can use this information to determine if memcached is taking a long time to return information to the client, during the read of the client operation or before returning and completing the operation. An example of the typical sequence for a set operation is provided below:

<32 new auto-negotiating client connection32: going from conn_new_cmd to conn_waiting32: going from conn_waiting to conn_read32: going from conn_read to conn_parse_cmd32: Client using the ascii protocol<32 set my_key 0 0 1032: going from conn_parse_cmd to conn_nread> NOT FOUND my_key>32 STORED32: going from conn_nread to conn_write32: going from conn_write to conn_new_cmd32: going from conn_new_cmd to conn_waiting32: going from conn_waiting to conn_read32: going from conn_read to conn_closing<32 connection closed.