Running memtier_benchmark falls into endless loop

[lubaihua33]

When the code with the commit id d6b9811 is merged, we test memtier benchmark falling into endless loop.
The test command is:
Server: memcached -u root -p 21789
Client: memtier_benchmark -s 10.10.10.5 -p 21789 -P memcache_text -x 3 -n 1000000 -t 1 -c 1 -d 4000 --ratio 1:1 --key-pattern S:S

Strace:

socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 6
setsockopt(6, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
setsockopt(6, SOL_SOCKET, SO_LINGER, {l_onoff=0, l_linger=0}, 8) = 0
setsockopt(6, SOL_TCP, TCP_NODELAY, [1], 4) = 0
fcntl(6, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(6, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
connect(6, {sa_family=AF_INET, sin_port=htons(21789), sin_addr=inet_addr("10.10.10.5")}, 16) = -1 EINPROGRESS (Operation now in progress)
epoll_ctl(3, EPOLL_CTL_ADD, 6, {EPOLLOUT, {u32=6, u64=6}}) = 0
write(2, "[RUN #1] Launching threads now.."..., 34[RUN #1] Launching threads now...
) = 34
mmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f7d44c8f000
mprotect(0x7f7d44c90000, 8388608, PROT_READ|PROT_WRITE) = 0
clone(child_stack=0x7f7d4548efb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f7d4548f9d0, tls=0x7f7d4548f700, child_tidptr=0x7f7d4548f9d0) = 77731
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 147, "[RUN #1 0%,   0 secs]  1 threads"..., 147[RUN #1 0%,   0 secs]  1 threads:          16 ops,      16 (avg:      16) ops/sec, 63.17KB/sec (avg: 63.17KB/sec),  0.17 (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 146, "[RUN #1 0%,   1 secs]  1 threads"..., 146[RUN #1 0%,   1 secs]  1 threads:          16 ops,       0 (avg:       8) ops/sec, 0.00KB/sec (avg: 31.56KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 146, "[RUN #1 0%,   3 secs]  1 threads"..., 146[RUN #1 0%,   3 secs]  1 threads:          16 ops,       0 (avg:       5) ops/sec, 0.00KB/sec (avg: 21.04KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 146, "[RUN #1 0%,   4 secs]  1 threads"..., 146[RUN #1 0%,   4 secs]  1 threads:          16 ops,       0 (avg:       3) ops/sec, 0.00KB/sec (avg: 15.78KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 146, "[RUN #1 0%,   5 secs]  1 threads"..., 146[RUN #1 0%,   5 secs]  1 threads:          16 ops,       0 (avg:       3) ops/sec, 0.00KB/sec (avg: 12.62KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 146, "[RUN #1 0%,   6 secs]  1 threads"..., 146[RUN #1 0%,   6 secs]  1 threads:          16 ops,       0 (avg:       2) ops/sec, 0.00KB/sec (avg: 10.52KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,   7 secs]  1 threads"..., 145[RUN #1 0%,   7 secs]  1 threads:          16 ops,       0 (avg:       2) ops/sec, 0.00KB/sec (avg: 9.01KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,   8 secs]  1 threads"..., 145[RUN #1 0%,   8 secs]  1 threads:          16 ops,       0 (avg:       1) ops/sec, 0.00KB/sec (avg: 7.89KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,   9 secs]  1 threads"..., 145[RUN #1 0%,   9 secs]  1 threads:          16 ops,       0 (avg:       1) ops/sec, 0.00KB/sec (avg: 7.01KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,  10 secs]  1 threads"..., 145[RUN #1 0%,  10 secs]  1 threads:          16 ops,       0 (avg:       1) ops/sec, 0.00KB/sec (avg: 6.31KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,  11 secs]  1 threads"..., 145[RUN #1 0%,  11 secs]  1 threads:          16 ops,       0 (avg:       1) ops/sec, 0.00KB/sec (avg: 5.74KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,  12 secs]  1 threads"..., 145[RUN #1 0%,  12 secs]  1 threads:          16 ops,       0 (avg:       1) ops/sec, 0.00KB/sec (avg: 5.26KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,  13 secs]  1 threads"..., 145[RUN #1 0%,  13 secs]  1 threads:          16 ops,       0 (avg:       1) ops/sec, 0.00KB/sec (avg: 4.85KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,  14 secs]  1 threads"..., 145[RUN #1 0%,  14 secs]  1 threads:          16 ops,       0 (avg:       1) ops/sec, 0.00KB/sec (avg: 4.51KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, 0x7ffe31d3c830) = 0
) = 145, "[RUN #1 0%,  15 secs]  1 threads"..., 145[RUN #1 0%,  15 secs]  1 threads:          16 ops,       0 (avg:       1) ops/sec, 0.00KB/sec (avg: 4.21KB/sec),  -nan (avg:  0.17) msec latency
nanosleep({tv_sec=1, tv_nsec=0}, ^Cstrace: Process 77730 detached

[yaacovhazan-Redislabs]

hi @lubaihua33, I have just seen that you also reply to the PR "fix issue #128 zeros in output #130", and want to make sure I understand... do you encountered the issue after commit id d6b9811 (version bump 1.3.0 (#124)) or de417c5 (fix issue #128 zeros in output (#130))?
if it's only after d6b9811, can you check please if de417c5 is resolving the issue?

[lubaihua33]

hi @lubaihua33, I have just seen that you also reply to the PR "fix issue #128 zeros in output #130", and want to make sure I understand... do you encountered the issue after commit id d6b9811 (version bump 1.3.0 (#124)) or de417c5 (fix issue #128 zeros in output (#130))?
if it's only after d6b9811, can you check please if de417c5 is resolving the issue?

It's "de417c5 (fix issue #128 zeros in output (#130))". After I revert "de417c5 (fix issue #128 zeros in output (#130))", I don't hit endless loop any more.

[yaacovhazan-Redislabs]

@lubaihua33 thank you... the issue relates to wrong disabling of the write event (before the test finished) ... I'll create a PR to fix it.

[lubaihua33]

@lubaihua33 thank you... the issue relates to wrong disabling of the write event (before the test finished) ... I'll create a PR to fix it.

@yaacovhazan-Redislabs Thank you.

[yossigo]

Fixed by #136