татко Крокодил

Всеки ден се убеждавам, че нищо не работи.

Открих забавен проблем с python и multiprocessing, който в момента още не мога да реша чий проблем е (в крайна сметка ще се окаже мой). Отне ми прилично количество време да го хвана и си струва да го разкажа.

Малко предистория: ползваме influxdb, в което тъпчем бая секундни данни, които после предъвкваме до минутни. InfluxDB има continuous queries, които вършат тази работа – на някакъв интервал от време хващат новите данни и ги сгъват. Тези заявки имаха няколко проблема:
– не се оправят с попълване на стари данни;
– изпълняват се рядко и минутните данни изостават;
– изпълняват се в общи линии в един thread, което кара минутните данни да изостават още повече (в нашия случай преди да ги сменим с около 12 часа).

Хванаха ме дяволите и си написах просто демонче на python, което да събира информация за различните бази какви данни могат да се сгънат, и паралелно да попълва данните. Работи в общи линии по следния начин:
– взима списък с базите данни
– пуска през multiprocessing-а да се събере за всяка база какви заявки трябва да се пуснат, на база на какви measurement-и има и докога са минутните и секундните данни в тях;
– пуска през multiprocessing-а събраните от предния pass заявки
– и така до края на света (или докато зависне).

След като навакса за няколко часа, успяваше да държи минутните данни в рамките на няколко минути от последните секундни данни, което си беше сериозно подобрение на ситуацията. Единственият проблем беше, че от време на време спираше да process-ва и увисваше.

Днес намерих време да го прегледам внимателно какво му се случва. Процесът изглежда като един parent и 5 fork()-нати child-а, като:
Parent-а спи във futex 0x22555a0;
Child 18455 във futex 0x7fdbfa366000;
Child 18546 read
Child 18457 във futex 0x7fdbfa366000
Child 18461 във futex 0x7fdbfa366000
Child 18462 във futex 0x7fdbfa366000
Child 18465 във futex 0x7fdbf908c2c0

Това не беше особено полезно, и се оказа, че стандартния python debugger (pdb) не може да се закача за съществуващи процеси, но за сметка на това gdb с подходящи debug символи може, и може да дава доста полезна информация. По този начин открих, че parent-а чака един child да приключи работата си:


#11 PyEval_EvalFrameEx (
f=f@entry=Frame 0x235fb80, for file /usr/lib64/python2.7/multiprocessing/pool.py, line 543, in wait (self== 1525137960000000000 AND time < 1525138107000000000 GROUP BY time(1m), * fill(linear)\' in a read only context, please use a POST request instead', u'level': u'warning'}], u'statement_id': 0}]}, None], _callback=None, _chunksize=1, _number_left=1, _ready=False, _success=True, _cond=<_Condition(_Verbose__verbose=False, _Condition__lock=, acquire=, _Condition__waiters=[], release=) at remote 0x7fdbe0015310>, _job=45499, _cache={45499: < ...>}) a...(truncated), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3040


Като в pool.py около ред 543 има следното:


class ApplyResult(object):

...

def wait(self, timeout=None):
self._cond.acquire()
try:
if not self._ready:
self._cond.wait(timeout)
finally:
self._cond.release()

Първоначално си мислех, че 18546 очаква да прочете нещо от грешното място, но излезе, че това е child-а, който е спечелил състезанието за изпълняване на следващата задача и чака да му я дадат (което изглежда се раздава през futex 0x7fdbfa366000). Един от child-овете обаче чака в друг lock:


(gdb) bt
#0 __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1 0x00007fdbf9b68dcb in _L_lock_812 () from /lib64/libpthread.so.0
#2 0x00007fdbf9b68c98 in __GI___pthread_mutex_lock (mutex=mutex@entry=0x7fdbf908c2c0 ) at ../nptl/pthread_mutex_lock.c:79
#3 0x00007fdbf8e846ea in _nss_files_gethostbyname4_r (name=name@entry=0x233fa44 "localhost", pat=pat@entry=0x7fdbecfcb8e0, buffer=buffer@entry=0x7fdbecfcb340 "hZ \372\333\177",
buflen=buflen@entry=1064, errnop=errnop@entry=0x7fdbecfcb8b0, herrnop=herrnop@entry=0x7fdbecfcb910, ttlp=ttlp@entry=0x0) at nss_files/files-hosts.c:381
#4 0x00007fdbf9170ed8 in gaih_inet (name=, name@entry=0x233fa44 "localhost", service=, req=req@entry=0x7fdbecfcbb90, pai=pai@entry=0x7fdbecfcb9f0,
naddrs=naddrs@entry=0x7fdbecfcb9e0) at ../sysdeps/posix/getaddrinfo.c:877
#5 0x00007fdbf91745cd in __GI_getaddrinfo (name=name@entry=0x233fa44 "localhost", service=service@entry=0x7fdbecfcbbc0 "8086", hints=hints@entry=0x7fdbecfcbb90, pai=pai@entry=0x7fdbecfcbb78)
at ../sysdeps/posix/getaddrinfo.c:2431
#6 0x00007fdbeed8760d in socket_getaddrinfo (self=, args=) at /usr/src/debug/Python-2.7.5/Modules/socketmodule.c:4193
#7 0x00007fdbf9e5fbb0 in call_function (oparg=, pp_stack=0x7fdbecfcbd10) at /usr/src/debug/Python-2.7.5/Python/ceval.c:4408
#8 PyEval_EvalFrameEx (
f=f@entry=Frame 0x7fdbe8013350, for file /usr/lib/python2.7/site-packages/urllib3/util/connection.py, line 64, in create_connection (address=('localhost', 8086), timeout=3000, source_address=None, socket_options=[(6, 1, 1)], host='localhost', port=8086, err=None), throwflag=throwflag@entry=0) at /usr/src/debug/Python-2.7.5/Python/ceval.c:3040

(gdb) frame 3
#3 0x00007fdbf8e846ea in _nss_files_gethostbyname4_r (name=name@entry=0x233fa44 "localhost", pat=pat@entry=0x7fdbecfcb8e0, buffer=buffer@entry=0x7fdbecfcb340 "hZ \372\333\177",
buflen=buflen@entry=1064, errnop=errnop@entry=0x7fdbecfcb8b0, herrnop=herrnop@entry=0x7fdbecfcb910, ttlp=ttlp@entry=0x0) at nss_files/files-hosts.c:381
381 __libc_lock_lock (lock);
(gdb) list
376 enum nss_status
377 _nss_files_gethostbyname4_r (const char *name, struct gaih_addrtuple **pat,
378 char *buffer, size_t buflen, int *errnop,
379 int *herrnop, int32_t *ttlp)
380 {
381 __libc_lock_lock (lock);
382
383 /* Reset file pointer to beginning or open file. */
384 enum nss_status status = internal_setent (keep_stream);
385


Или в превод – опитваме се да вземем стандартния lock, който libc-то използва за да си пази reentrant функциите, и някой го държи. Кой ли?


(gdb) p lock
$3 = {__data = {__lock = 2, __count = 0, __owner = 16609, __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
__size = "\002\000\000\000\000\000\000\000\341@\000\000\001", '\000' , __align = 2}
(gdb) p &lock
$4 = (__libc_lock_t *) 0x7fdbf908c2c0


Тук се вижда как owner-а на lock-а всъщност е parent-а. Той обаче не смята, че го държи:


(gdb) p lock
$2 = 0
(gdb) p &lock
$3 = (__libc_lock_t *) 0x7fdbf9450df0
(gdb) x/20x 0x7fdbf9450df0
0x7fdbf9450df0 : 0x00000000 0x00000000 0x00000000 0x00000000
0x7fdbf9450e00 <__abort_msg>: 0x00000000 0x00000000 0x00000000 0x00000000
0x7fdbf9450e10 : 0x00000000 0x00000000 0x00000000 0x00000000
0x7fdbf9450e20 : 0x00000000 0x00000000 0x00000000 0x00000000
0x7fdbf9450e30 : 0x001762c9 0x00000000 0x00000000 0x00000000

… което е и съвсем очаквано, при условие, че са два процеса и тая памет не е обща.

Та, явно това, което се е случило е, че докато parent-а е правел fork(), тоя lock го е държал някой, и child-а реално не може да пипне каквото и да е, свързано с него (което значи никакви reentrant функции в glibc-то, каквито па всички ползват (и би трябвало да ползват)). Въпросът е, че по принцип това не би трябвало да е възможно, щото около fork() няма нищо, което да взима тоя lock, и би трябвало glibc да си освобождава lock-а като излиза от функциите си.

Първоначалното ми идиотско предположение беше, че в signal handler-а на SIGCHLD multiprocessing модула създава новите child-ове, и така докато нещо друго държи lock-а идва сигнал, прави се нов процес и той го “наследява” заключен. Това беше твърде глупаво, за да е истина, и се оказа, че не е…

Около въпросите с lock-а бях стигнал с търсене до две неща – issue 127 в gperftools и Debian bug 657835. Първото каза, че проблемът ми може да е от друг lock, който някой друг държи преди fork-а (което ме накара да се загледам по-внимателно какви lock-ове се държат), а второто, че като цяло ако fork-ваш thread-нато приложение, може после единствено да правиш execve(), защото всичко друго не е ясно колко ще работи.

И накрая се оказа, че ако се ползва multiprocessing модула, той пуска в главния процес няколко thread-а, които да се занимават със следенето и пускането на child-ове за обработка. Та ето какво реално се случва:

– някой child си изработва нужния брой операции и излиза
– parent-а получава SIGCHLD и си отбелязва, че трябва да види какво става
– главния thread на parent-а тръгва да събира списъка бази, и вика в някакъв момент _nss_files_gethostbyname4_r, който взима lock-а;
– по това време другия thread казва “а, нямам достатъчно child-ове, fork()”
– profit.

Текущото ми глупаво решение е да не правя нищо в главния thread, което може да взима тоя lock и да се надявам, че няма още някой такъв. Бъдещото ми решение е или да го пиша на python3 с някой друг модул по темата, или на go (което ще трябва да науча).

Tags: работа

This entry was posted on Thursday, May 3rd, 2018 at 11:41 and is filed under General. You can follow any responses to this entry through the RSS 2.0 feed. You can skip to the end and leave a response. Pinging is currently not allowed.