2018-05-03 python, multiprocessing, thread-ове и забивания

by Vasil Kolev

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

Открих забавен проблем с 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:

4 Responses to “2018-05-03 python, multiprocessing, thread-ове и забивания”

  1. кунев Says:

    „Хванаха ме дяволите и си написах просто демонче на python…“
    „Бъдещото ми решение е или да го пиша на python3…“

    THIS IS WHY WE CAN’T HAVE NICE THINGS!!!

  2. Vasil Kolev Says:

    @кунев, не схващам… Проблемът е, че не съм patch-нал influx-а или че не съм почнал с python3? За първото – не знам go, за второто – 1) не знам дали ще ми реши проблема и имам лошо предчувствие, 2) на много места, където deploy-ваме някакъв код просто няма python3 и не ми е било даже опция досега…

  3. кунев Says:

    Patch-ването на influx-а най-вероятно не е тривиално, пък и не е супер яко да си правиш сам пачове за база. ‘Ептен па ако трябва те първа да учиш езика. Дори да извадиш късмет и да не съсипеш нищо, толко’ ш’а боли процеса, че не си струва.

    It is the current year, обаче и никой не бива да е поставян в ситуация, в която да казва неиронично неща като „на много места, където deploy-ваме някакъв код просто няма python3“. Незаинтересоваността на всичкото програмист и всичкото админ да реши тоя проблем ми е много тежък психологически trigger и лесно стигам до профанизми по темата. Няма как се знае, предвид, че т’ва явно е относително екзотичен бъг, но има голям шанс пренаписването на версия на нещо, което не е major версията от преди 10 години, да помогне значително.

    Иначе решението да не правиш нищо в main thread-а, освен че те спасява от мъките, най-вероятно прави и нещата една идея по-лесни за четене и осмисляне в последствие, така че не е точно глупаво.

    Отделно съм изкушен да питам do you have some time to talk about our lord and saviour asyncio, ама подозирам, че мачкането на тия данни включва нетривиално CPU натоварване в себе си, така че да всъщност си е съвсем като за multiprocessing.

  4. Vasil Kolev Says:

    @кунев, за patch-ването съм напълно съгласен.

    За ситуацията – нямам особен избор. Клиентите наполовина живеят на centos6, който има support до 2020, и не ги виждам да upgrade-ват преди това, щото ще е доста болезнено, за някои направо невъзможно.

    Да не правя конкретното trigger-ващо действие в main thread-а всъщност прави кода по-гаден, но не особено, та го преживях.

    А за asyncio, вероятно ще ми реши проблема – аз не дъвча данните в python-а, multiprocessing-а ми е просто да имам няколко паралелни заявки към influx-а, вместо идиотски да се изчакват. Трябва да погледна как изглежда интерфейса и колко ще му се дразня. Задачата сама по себе си изглежда така:

    първи пас – мини през всички бази, вземи края на retention policy-тата (т.е. докъде има данни), и изгенерирай заявки за попълване на дупката, с някакви граници.

    втори пас – изпълни заявките.

    Всичкото това няма никакви сметки в питона, може да се напише както си иска човек с каквото си иска, просто ми се щеше да е просто и кратко, вместо да забивам в някакви битовизми (ако беше на C, parse-ване на string-ове и json, например).

Leave a Reply