High CPU usage when unpacking on Ubuntu 12.04 with msgpack 4.8

[imcom]

(gdb) bt
#0  0x00007fee03ef525d in sem_post () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x000000000056d237 in PyThread_release_lock (lock=0x27bd4f0) at ../Python/thread_pthread.h:346
#2  0x000000000051a1fd in PyEval_EvalFrameEx (
    f=Frame 0x2ac03c0, for file /usr/local/lib/python2.7/dist-packages/msgpack/fallback.py, line 537, in _fb_unpack (self=<Unpacker(_max_buffer_size=2147483647, _encoding=None, _max_map_len=2147483647, _max_bin_len=2147483647, _max_ext_len=2147483647, _fb_sloppiness=0, _object_hook=None, _fb_buf_o=52492, _fb_buf_n=1866623, _fb_buf_i=22, _unicode_errors='strict', _use_list=True, _max_str_len=2147483647, _ext_hook=<type at remote 0x17ed550>

Recently, I've been observing this strange situation that my script just simply receives msgpack-ed data from stdin and extracts it. However, during that procedure, the script causes sever futex contention. I've used gdb to track it down and found out that there are tons of require and release on the same lock object, e.g. "lock=0x27bd4f0", which seems to me that is used by msgpack, specifically _fb_unpack.

Just wondering has anyone else observed similar phenomenon ? I have not got time to dig into the _fb_unpack function so currently I have no idea why this function can cause futex contention.

futex(0x27bd4f0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x27bd4f0, FUTEX_WAIT_PRIVATE, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x27bd4f0, FUTEX_WAIT_PRIVATE, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x27bd4f0, FUTEX_WAKE_PRIVATE, 1) = 1

[methane]

CPython and msgpack-python version?
How did you install it (binary wheel? source package? from git?)

[jfolz]

There are no locks in the fallback code itself. The only place I could imagine where a lock might hide is in the file-like/buffer object that is being read.

[imcom]

@methane In my dev env, I have Python 2.7.3 which is distributed with Ubuntu12.04 and msgpack-python==0.4.8
I installed msgpack-python via pip. pip install msgpack-python

@jfolz It is very likely because I am actually running this in Multi-language Storm 0.9.3 where the python scripts talk to each other via stdin/stdout. So probably the stdin is the culprit? Correct me if I got this wrong, but should not be that the read should be one time action? Also the weird thing is this contention does not happen on our production environment (Python 2.7.6/2.7.8, Ubuntu 14.04)

[imcom]

In Storm topology, the python bolt (script) receives a message from Kafka every minute, so there should not be a lot of R/W ops that cause contention. Unless, there is buffer somewhere and the buffer is far less then the message size so each message will be chopped into many pieces to fit in the buffer? But then I assume msgpack will have to wait until the chopped messages to assemble so that it can proceed with unpacking ?

[jfolz]

The pure Python fallback doesn't seem to do read-ahead. The C extension does. If you install cython and then reinstall msgpack, this will probably go away.

[methane]

fallbacback.py:537 in msgpack 0.4.8 is just a recursive call to _fb_unpack()
The futex is very normal behavior of Python.
@imcom Why did you think these futexes are "contention"?

If these are really contention, you may use multithreading. CPython 2 is very bad at running
CPU bound task in multiple threads. Use process.

[imcom]

@jfolz I will give it a shot, thanks for your advice

[imcom]

@methane because I observed severe high CPU usage and it also caused the data processing being delayed. On servers do not have this contention, the data processing should be finished less than a second, however this problematic server uses like 15 minutes to do less job. It is completely out of normal as I checked the distribution of sys calls at run time, it was like 99% calls/times were spent on the lock object.
Multi-threading might make sense but I actually have no control over that because it is the behaviour of Pyleus (Python-Strom library).
I will try to reproduce this contention without Storm/multithreading involved so we will hopefully have a clearer picture

[imcom]

strace -c -p 22762
Process 22762 attached - interrupt to quit
^CProcess 22762 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0        12           read
  -nan    0.000000           0         8           write
  -nan    0.000000           0         3           stat
  -nan    0.000000           0         9           mmap
  -nan    0.000000           0        35           munmap
  -nan    0.000000           0         9           mremap
  -nan    0.000000           0         3           sendto
  -nan    0.000000           0      4572      1758 futex
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                  4651      1758 total

I am not using python-msgpack with CPython

[methane]

I am not using python-msgpack with CPython

Do you mean, futex is called many times without msgpack-python, right?

[imcom]

@methane sorry for the confusion, but the futex is called from msgpack-python, around here

/usr/local/lib/python2.7/dist-packages/msgpack/fallback.py, line 537, in _fb_unpack

This is what confuses me a lot because I do not really see why the futex being crazily called on a method like unpack...

If these are really contention, you may use multithreading. CPython 2 is very bad at running
CPU bound task in multiple threads. Use process.

for CPython part, I am just saying I did not use CPython, so this contention is not related to CPython. Most likely the multithreading is the culprit here but I have not found out why because this contention does not happen on all servers ...

[methane]

called many times != contention.
Why do you think it's contention?

(gdb) bt
#0  0x00007fee03ef525d in sem_post () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x000000000056d237 in PyThread_release_lock (lock=0x27bd4f0) at ../Python/thread_pthread.h:346
#2  0x000000000051a1fd in PyEval_EvalFrameEx (
    f=Frame 0x2ac03c0, for file /usr/local/lib/python2.7/dist-packages/msgpack/fallback.py, line 537, in _fb_unpack (self=<Unpacker(_max_buffer_size=2147483647, _encoding=None, _max_map_len=2147483647, _max_bin_len=2147483647, _max_ext_len=2147483647, _fb_sloppiness=0, _object_hook=None, _fb_buf_o=52492, _fb_buf_n=1866623, _fb_buf_i=22, _unicode_errors='strict', _use_list=True, _max_str_len=2147483647, _ext_hook=<type at remote 0x17ed550>

You cut important imformation. C level file:line of #2 and #3.

[imcom]

OK, let's not call it a contention for now. I grabbed a normal one, strace the calls give me the below

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.88    1.191156          51     23360           select
  0.07    0.000859          17        51           poll
  0.02    0.000271          16        17           sendto
  0.02    0.000255           2       124        56 futex
  0.00    0.000015           0        34           recvfrom
------ ----------- ----------- --------- --------- ----------------
100.00    1.192556                 23586        56 total

This one makes sense to me because there should be only one thread which is constantly reading from a pipe and processing the data it receives. So many calls to select is eligible and only a few futex calls as there should not be many places that a lock is required.

I will get the backtrace again for more intel, thanks for your attention ) But I will need to see if I have sufficient debug symbols to provide what you need

[methane]

I grabbed a normal one

What is normal? Is it a multi threading program???

[imcom]

It is a multithreading program. The strace -c result I just posted is from a normal behaviour, where you can see a log of select calls and much less futex calls. With this, the CPU usage is around 8% on a 24-cores virtual machine running CentOS-7.

On the other hand, on the problematic server, the same program uses up to ~100% CPU.
The below result makes me think there is sth. out of normal

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0        28           read
  -nan    0.000000           0         2           write
  -nan    0.000000           0         3           stat
  -nan    0.000000           0        28           mmap
  -nan    0.000000           0        37           munmap
  -nan    0.000000           0        28           mremap
  -nan    0.000000           0         3           sendto
  -nan    0.000000           0      6441      1496 futex
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                  6570      1496 total