Bug report
Bug description:
Multithread program hangs over 20 seconds when execute PyOS_AfterFork_Child()
The background of the issue is as follows: Incident #111635 had previously encountered this problem, but it was only a speculation without strace information. The issue has recurred, and this time, crucial information was captured using strace. It was discovered that there is a significant delay in executing PyOS_AfterFork_Child().
The pty.fork() method was called at intervals of 10 seconds to fork two subprocesses. One subprocess was blocked for 21 seconds, and the other for 12 seconds. Both subprocesses executed the getrandom call at the same time, precisely at 1701835831 seconds. This getrandom call originates from the random.py module.
if hasattr(_os, "fork"):
_os.register_at_fork(after_in_child=_inst.seed)This indicates that the code is blocking in PyOS_AfterFork_Child() and not in the business logic code.
The captured strace results are as follows:
child process 1：
553976: [pid 33616] 1701835810.183378 (+ 0.000096) futex(0xaaaac440e934, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=12811139, tv_nsec=527515848}, FUTEX_BITSET_MATCH_ANY/home/sopuser/strace: Process 221693 attached
553978: [pid 41665] 1701835810.183500 (+ 0.000121) <... clone resumed>, child_tidptr=0xfffe767fc2b0) = 221693
553979: [pid 221693] 1701835810.183519 (+ 0.000018) set_robust_list(0xfffe767fc2c0, 24) = 0
553987: [pid 221693] 1701835810.184342 (+ 0.000019) close(197 <unfinished ...>
553990: [pid 221693] 1701835810.184391 (+ 0.000021) <... close resumed>) = 0
553993: [pid 221693] 1701835810.184445 (+ 0.000018) setsid( <unfinished ...>
553997: [pid 221693] 1701835810.184508 (+ 0.000015) <... setsid resumed>) = 221693
553999: [pid 221693] 1701835810.184533 (+ 0.000014) ioctl(199, TIOCSCTTY, 0 <unfinished ...>
554001: [pid 221693] 1701835810.184584 (+ 0.000030) <... ioctl resumed>) = 0
554002: [pid 221693] 1701835810.184610 (+ 0.000026) dup3(199, 0, 0 <unfinished ...>
554004: [pid 221693] 1701835810.184648 (+ 0.000017) <... dup3 resumed>) = 0
554005: [pid 221693] 1701835810.184710 (+ 0.000061) dup3(199, 1, 0 <unfinished ...>
554007: [pid 221693] 1701835810.184786 (+ 0.000055) <... dup3 resumed>) = 1
554008: [pid 221693] 1701835810.184825 (+ 0.000039) dup3(199, 2, 0) = 2
554009: [pid 221693] 1701835810.184871 (+ 0.000045) close(199) = 0
554036: [pid 221693] 1701835810.186657 (+ 0.000358) --- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} ---
554116: [pid 41665] 1701835810.209502 (+ 0.000019) wait4(221693, <unfinished ...>
583902: [pid 221693] 1701835816.220084 (+ 0.082158) munmap(0xffff74017000, 262144) = 0
613207: [pid 221693] 1701835822.684039 (+ 0.000027) munmap(0xffff54091000, 262144 <unfinished ...>
613209: [pid 221693] 1701835822.684179 (+ 0.000016) <... munmap resumed>) = 0
613638: [pid 221693] 1701835822.906848 (+ 0.000020) munmap(0xffff340a9000, 262144 <unfinished ...>
613640: [pid 221693] 1701835822.906965 (+ 0.000014) <... munmap resumed>) = 0
621879: [pid 221693] 1701835824.576367 (+ 0.000039) munmap(0xffff54111000, 262144 <unfinished ...>
621881: [pid 221693] 1701835824.576499 (+ 0.000028) <... munmap resumed>) = 0
625804: [pid 221693] 1701835827.648797 (+ 0.000030) munmap(0xffff341a9000, 262144 <unfinished ...>
625806: [pid 221693] 1701835827.648943 (+ 0.000016) <... munmap resumed>) = 0
625812: [pid 221693] 1701835828.397225 (+ 0.000032) munmap(0xffff541d2000, 262144 <unfinished ...>
625814: [pid 221693] 1701835828.397341 (+ 0.000017) <... munmap resumed>) = 0
626783: [pid 221693] 1701835830.500730 (+ 0.000029) munmap(0xffff54312000, 262144 <unfinished ...>
626785: [pid 221693] 1701835830.500859 (+ 0.000019) <... munmap resumed>) = 0
627149: [pid 221693] 1701835830.640895 (+ 0.000027) munmap(0xffff1433b000, 262144 <unfinished ...>
627151: [pid 221693] 1701835830.641000 (+ 0.000017) <... munmap resumed>) = 0
630660: [pid 221693] 1701835831.131919 (+ 0.000031) munmap(0xffff14474000, 262144 <unfinished ...>
630663: [pid 221693] 1701835831.132038 (+ 0.000014) <... munmap resumed>) = 0
631283: [pid 221693] 1701835831.321527 (+ 0.133318) munmap(0xffff34539000, 262144) = 0
631285: [pid 221693] 1701835831.353549 (+ 0.031356) munmap(0xffff14574000, 262144) = 0
631288: [pid 221693] 1701835831.362103 (+ 0.000042) munmap(0xffff545b9000, 262144 <unfinished ...>
631290: [pid 221693] 1701835831.362232 (+ 0.000019) <... munmap resumed>) = 0
631291: [pid 221693] 1701835831.407125 (+ 0.044904) munmap(0xffff54679000, 262144 <unfinished ...>
631293: [pid 221693] 1701835831.407299 (+ 0.000119) <... munmap resumed>) = 0
631295: [pid 221693] 1701835831.416886 (+ 0.000043) munmap(0xffff546b9000, 262144 <unfinished ...>
631297: [pid 221693] 1701835831.416988 (+ 0.000026) <... munmap resumed>) = 0
631299: [pid 221693] 1701835831.417224 (+ 0.000070) munmap(0xffff146bc000, 262144) = 0
631300: [pid 221693] 1701835831.495524 (+ 0.078310) munmap(0xffff54779000, 262144) = 0
631302: [pid 221693] 1701835831.505880 (+ 0.010107) munmap(0xffff347b9000, 262144) = 0
631303: [pid 221693] 1701835831.506037 (+ 0.000148) munmap(0xfffe717f3000, 8392704 <unfinished ...>
631306: [pid 221693] 1701835831.506536 (+ 0.000092) <... munmap resumed>) = 0
631308: [pid 221693] 1701835831.508588 (+ 0.001762) getrandom("\x80\x72\xf7\x4d\xa9\x9f\xca\xa9\xdd\x43\x86\x4c\x26\x89\x22\x0b\xe7\xc2\xa1\xd6\x60\x01\xe5\x82\x2a\x3f\x22\x49\xcb\x1c\x53\x57\xf0\xc2\x57\x15\x16\xd8\x7f\xd2\x04\x90\x45\xf8\x7b\xef\xf2\xd2\xdf\x3d\x0c\xf0\x04\x9b\xd2\x37\x9a\x75\x02\xef\x54\xdf\xe5\xbb\x76\x58\x76\xe4\x2b\x42\x1f\x94\x28\xb5\x65\x4a\x0d\xf8\xc1\xfe\xa3\xc5\x77\x07\x0d\x9a\x67\x87\xaf\x20\xcc\x87\x08\x2b\x50\x3b\x59\x55\x5c\x89\x47\xb0\x2a\xbc\xbc\xaa\x91\xd7\xdb\x92\x18\x12\x82\x46\x5e\x3e\xff\x3c\x95\x43\x7d\x37\x2d\xfe\x16\x5d\xd1\x2c\x31\xba\x83\xfa\x11\x63\xb8\x3e\x6e\x90\xfb\x05\x90\xde\xb4\xf9\x93\x54\xf0\xed\x69\x16\x31\x90\x87\x02\xd2\x62\xae\x24\x02\xff\xd6\x89\x6a\xf8\x14\xf5\x52\xc2\xbf\x82\x73\x2e\x80\xd2\xf3\x99\xef\xb0\x4a\x36\x1f\x83\xbf\x8b\x32\x70\xcd\xd6\xd9\x11\x2d\x41\x74\x53\xf8\x0f\x2f\xdf\xdc\xff\x1a\x29\xbf\x6c\x7c\x97\xd3\x2c\x4e\x30\x62\x53\xc0\xad\x2a\x0d\x8e\x01\xb1\xe9\x37\x4c\xc0\x7a\x23\xb6\xdf\x30\xa9\x39\x7f\xf0\xfd\x5c\xe9\x6f\xd6\xc8\x80\x19\xdb\x2b\x24\x90\xee\xca\x10\x9b\x73\xeb\x39\xc2\x33\x13\xf9\x53\x08\x7e\x23\x67\x25\x14\xc3\x6e\x0f\x2c\xda\x22\x0f\x7d\x6b\x6e\x60\xca\xf0\x1b\xf0\x1a\x19\xca\x0f\xa0\x21\x6a\x1c\x4c\x1d\x18\x63\xb1\xdf\x38\x1a\xfc\xa0\x67\x76\x5a\xe3\x17\xa6\x90\x16\xdb\x50\xe5\x53\x48\x2a\x74\xfd\xa1\xa1\xf6\xec\x31\xb3\x6c\x4d\x4e\x7b\xef\x8c\x75\x38\xf4\x7a\xc4\xb0\xb3\x17\xea\x18\x6c\xf5\x8a\xd7\x89\x95\xfc\x45\x5f\x94\x37\x85\x8b\x3a\x41\xb0\xf3\x9e\xcb\x75\xbb\x08\x3e\x75\x8d\xb5\x61\xc8\xb7\x58\x06\x6c\x5b\xfb\x42\x88\x68\x95\x84\xcf\x44\x30\x34\x9f\xa8\x75\x7a\x85\x06\xe4\xbb\x4a\xf7\xbc\x63\x23\x86\x91\xd3\x2e\x74\xd3\x1c\x1a\x12\x8c\x85\x2e\xc3\x1b\xa6\xda\xb9\x8e\xbb\x4b\x6a\x41\xb7\xb6\x80\xe7\x12\x98\x28\xa2\x32\x2c\x10\x89\xd2\xcb\x99\x92\x16\xff\x82\xfb\xf7\x2e\x83\xbe\xff\x47\xe3\x6c\x19\x17\x22\x33\x4a\x43\x07\x2d\xcf\x56\xeb\xb5\xf9\x72\xd5\xd6\xa9\xad\x9b\x48\x8e\x71\xa6\xe1\xa9\x3d\x54\x26\x80\xb1\x5a\x3f\x2d\x72\x39\xee\x97\x1f\x78\x2e\xa7\xd3\x79\xc1\x0a\xe6\xba\x60\xb7\x6d\xb1\xd9\xb ...
631532: [pid 221693] 1701835831.523553 (+ 0.000247) setsid( <unfinished ...>
631534: [pid 221693] 1701835831.523615 (+ 0.000039) <... setsid resumed>) = -1 EPERM (Operation not permitted)
631565: [pid 221693] 1701835831.525115 (+ 0.000017) ioctl(0, TIOCSWINSZ, {ws_row=1920, ws_col=1080, ws_xpixel=0, ws_ypixel=0} <unfinished ...>
631568: [pid 221693] 1701835831.525200 (+ 0.000014) <... ioctl resumed>) = 0
631571: [pid 221693] 1701835831.525273 (+ 0.000016) ioctl(0, TCGETS <unfinished ...>
631574: [pid 221693] 1701835831.525335 (+ 0.000014) <... ioctl resumed>, {B38400 opost isig icanon echo ...}) = 0
631577: [pid 221693] 1701835831.525434 (+ 0.000016) ioctl(0, TCGETS <unfinished ...>
631580: [pid 221693] 1701835831.525492 (+ 0.000014) <... ioctl resumed>, {B38400 opost isig icanon echo ...}) = 0
631582: [pid 221693] 1701835831.525551 (+ 0.000024) ioctl(0, SNDCTL_TMR_START or TCSETS, {B38400 opost isig icanon -echo ...}) = 0
631583: [pid 221693] 1701835831.525595 (+ 0.000044) ioctl(0, TCGETS, {B38400 opost isig icanon -echo ...}) = 0
631584: [pid 221693] 1701835831.525653 (+ 0.000058) prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=4*1024, rlim_max=1000000}) = 0
child process 2:
596489: [pid 41662] 1701835819.363051 (+ 0.000077) clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD/home/sopuser/strace: Process 221796 attached
596490: , child_tidptr=0xfffe777fe2b0) = 221796
596491: [pid 221796] 1701835819.367270 (+ 0.004227) set_robust_list(0xfffe777fe2c0, 24) = 0
596493: [pid 221796] 1701835819.368103 (+ 0.000440) close(200) = 0
596494: [pid 221796] 1701835819.368160 (+ 0.000055) setsid( <unfinished ...>
596496: [pid 221796] 1701835819.368221 (+ 0.000039) <... setsid resumed>) = 221796
596498: [pid 221796] 1701835819.368251 (+ 0.000014) ioctl(201, TIOCSCTTY, 0) = 0
596499: [pid 221796] 1701835819.368299 (+ 0.000048) dup3(201, 0, 0) = 0
596500: [pid 221796] 1701835819.368347 (+ 0.000047) dup3(201, 1, 0) = 1
596501: [pid 221796] 1701835819.368390 (+ 0.000044) dup3(201, 2, 0) = 2
596502: [pid 221796] 1701835819.368436 (+ 0.000044) close(201) = 0
596504: [pid 41662] 1701835819.369142 (+ 0.000346) wait4(221796, 0xfffe777face4, WNOHANG, NULL) = 0
613206: [pid 221796] 1701835822.683999 (+ 0.375762) munmap(0xffff54091000, 262144 <unfinished ...>
613208: [pid 221796] 1701835822.684161 (+ 0.000123) <... munmap resumed>) = 0
613637: [pid 221796] 1701835822.906819 (+ 0.005902) munmap(0xffff340a9000, 262144 <unfinished ...>
613639: [pid 221796] 1701835822.906950 (+ 0.000102) <... munmap resumed>) = 0
621878: [pid 221796] 1701835824.576320 (+ 0.632095) munmap(0xffff54111000, 262144 <unfinished ...>
621880: [pid 221796] 1701835824.576470 (+ 0.000102) <... munmap resumed>) = 0
625803: [pid 221796] 1701835827.648757 (+ 0.335422) munmap(0xffff341a9000, 262144 <unfinished ...>
625805: [pid 221796] 1701835827.648926 (+ 0.000129) <... munmap resumed>) = 0
625811: [pid 221796] 1701835828.397184 (+ 0.415578) munmap(0xffff541d2000, 262144 <unfinished ...>
625813: [pid 221796] 1701835828.397323 (+ 0.000097) <... munmap resumed>) = 0
626782: [pid 221796] 1701835830.500692 (+ 0.037784) munmap(0xffff54312000, 262144 <unfinished ...>
626784: [pid 221796] 1701835830.500837 (+ 0.000108) <... munmap resumed>) = 0
627148: [pid 221796] 1701835830.640857 (+ 0.045355) munmap(0xffff1433b000, 262144 <unfinished ...>
627150: [pid 221796] 1701835830.640982 (+ 0.000087) <... munmap resumed>) = 0
630659: [pid 221796] 1701835831.131875 (+ 0.010296) munmap(0xffff14474000, 262144 <unfinished ...>
630662: [pid 221796] 1701835831.132023 (+ 0.000026) <... munmap resumed>) = 0
631284: [pid 221796] 1701835831.322199 (+ 0.000665) munmap(0xffff34539000, 262144) = 0
631286: [pid 221796] 1701835831.355685 (+ 0.002130) munmap(0xffff14574000, 262144) = 0
631287: [pid 221796] 1701835831.362052 (+ 0.006367) munmap(0xffff545b9000, 262144 <unfinished ...>
631289: [pid 221796] 1701835831.362212 (+ 0.000109) <... munmap resumed>) = 0
631292: [pid 221796] 1701835831.407180 (+ 0.000044) munmap(0xffff54679000, 262144) = 0
631294: [pid 221796] 1701835831.416833 (+ 0.009542) munmap(0xffff546b9000, 262144 <unfinished ...>
631296: [pid 221796] 1701835831.416960 (+ 0.000074) <... munmap resumed>) = 0
631298: [pid 221796] 1701835831.417154 (+ 0.000166) munmap(0xffff146bc000, 262144) = 0
631301: [pid 221796] 1701835831.495780 (+ 0.000247) munmap(0xffff54779000, 262144) = 0
631304: [pid 221796] 1701835831.506236 (+ 0.000198) munmap(0xffff347b9000, 262144) = 0
631305: [pid 221796] 1701835831.506443 (+ 0.000207) munmap(0xfffe717f3000, 8392704 <unfinished ...>
631307: [pid 221796] 1701835831.506835 (+ 0.000299) <... munmap resumed>) = 0
631309: [pid 221796] 1701835831.509133 (+ 0.000539) getrandom("\xbf\x80\x8a\x5c\xd3\x09\xc6\xf7\x1a\x43\x7c\xd4\x38\x90\xc3\x1a\x6f\xab\x33\xcc\x69\x15\x0a\x90\x90\x5a\x04\x53\x79\x2e\x75\xe9\x67\x51\x4b\x8b\x69\x0f\x7e\x6b\x2f\xd0\x3a\xdf\xa5\xfe\xdc\x6d\x0d\x36\x22\x37\x0f\xe5\x11\x74\xc2\x3c\x1d\x43\xa1\x70\x97\x1b\xd1\xde\xbb\x2a\x22\xe7\xf7\xa4\xf7\xed\x1f\x1e\x13\x67\x92\x82\x6b\x87\x5a\xd2\x25\x1c\xc2\x50\x85\x8f\x6b\x25\xaf\xf9\xa9\x47\x02\x85\x70\x86\xff\xdf\x5f\xe5\xac\xfc\x1b\x56\xc4\x93\x04\x0b\xef\x98\xf4\x5c\x4e\xe8\xac\x17\x56\x82\xee\xae\xb5\xa4\xcc\x8f\x38\xe3\xfa\x16\x64\xac\x65\x51\x54\x12\x63\x26\x5d\xaf\xa9\x8d\xf8\x43\xc9\x32\x0f\x54\x66\x80\x64\x01\xcd\x0b\xfa\x12\x62\xa8\x5e\xec\x5f\xa6\xb4\xbb\x98\xab\x8d\xa4\x79\xe0\xfb\x52\xa9\xe1\xee\xcf\xf1\x76\xd0\x30\x21\x69\x4c\xa5\x3c\xe7\xa7\x46\xe5\x6d\x41\xc2\x6a\xc1\x7e\xd5\xfb\xa1\xc9\x27\x7e\xc5\x33\xaf\x4f\x3b\x72\x26\x6a\xe3\x5f\xef\x52\xb6\x88\xa2\x0a\x3a\x6b\xb4\x50\xf7\x7c\x34\x38\x73\x11\x71\xac\x8f\xf0\x47\xf6\x55\x13\x67\x13\x8b\x50\x1d\xb9\x8b\xfb\x65\x30\x6c\x62\x93\xb2\xe3\xb3\x6e\xbc\xf0\x8f\x74\xe7\x62\x52\x2a\xbc\x72\xce\xad\xeb\xd2\x60\xab\x56\x79\x6c\x30\xa8\x51\x5f\xdc\x95\xaa\xd8\x67\x07\x50\xae\x25\x1c\xe7\x0a\xf5\xc0\x02\x14\x80\x57\x64\xad\xbb\xfd\x1b\x60\xf4\x82\xff\xb0\x69\xc1\x79\x6b\x65\xae\x51\xac\xb9\x1f\xa3\xc1\x3d\xf4\xff\x99\x72\xd4\xaa\x8d\x1a\xa0\x80\x3f\x35\x57\x46\xfc\xe9\xea\x0f\xb6\x03\x4b\xad\xd0\xef\xfd\xb0\x55\x11\x63\xed\xfd\x64\xb1\xd6\x53\xaa\xa3\x14\x2d\x45\xbb\xd8\xe7\x67\xb4\x09\xf4\x6d\x14\x90\xde\xea\xd7\xfe\x8d\xf1\xfb\x16\xab\x52\x47\x0e\xb7\xb1\xc0\xa9\xfa\x53\xcd\x6c\x4b\xd1\x31\x77\x14\xba\x63\x13\x58\x1d\x83\xe5\xfb\x65\x25\x2f\x58\x91\xeb\x8f\x11\x85\x16\xd8\xe1\x40\xd5\x22\x43\xfd\x23\x7c\x8e\xee\x31\x99\xa1\x5e\xb6\x0f\xf8\xac\xd8\x0c\x54\xe4\x62\xd4\x6e\x83\x62\x64\xe5\xe3\x29\x0f\x32\x47\x40\x94\x85\x85\x93\x00\xe4\x85\xaa\xd0\x82\xdf\x4c\x2f\x11\x9b\x3a\x8c\x52\x36\x7a\x92\x8d\xc5\x7b\x93\x78\x6c\x68\x9b\x95\x17\xb7\xd7\x10\x0a\x8a\x0a\x51\x26\xe9\xb2\xb9\x05\xda\xc ...
631310: [pid 221796] 1701835831.510644 (+ 0.001510) setsid() = -1 EPERM (Operation not permitted)
631311: [pid 221796] 1701835831.510935 (+ 0.000286) ioctl(0, TIOCSWINSZ, {ws_row=1920, ws_col=1080, ws_xpixel=0, ws_ypixel=0}) = 0
631312: [pid 221796] 1701835831.511028 (+ 0.000091) ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
631313: [pid 221796] 1701835831.511126 (+ 0.000098) ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
631314: [pid 221796] 1701835831.511176 (+ 0.000049) ioctl(0, SNDCTL_TMR_START or TCSETS, {B38400 opost isig icanon -echo ...}) = 0
631315: [pid 221796] 1701835831.511229 (+ 0.000052) ioctl(0, TCGETS, {B38400 opost isig icanon -echo ...}) = 0
631316: [pid 221796] 1701835831.512789 (+ 0.001561) prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=4*1024, rlim_max=1000000}) = 0
CPython versions tested on:
3.9
Operating systems tested on:
Linux
Bug report
Bug description:
Multithread program hangs over 20 seconds when execute PyOS_AfterFork_Child()
The background of the issue is as follows: Incident #111635 had previously encountered this problem, but it was only a speculation without
straceinformation. The issue has recurred, and this time, crucial information was captured usingstrace. It was discovered that there is a significant delay in executingPyOS_AfterFork_Child().The
pty.fork()method was called at intervals of 10 seconds to fork two subprocesses. One subprocess was blocked for 21 seconds, and the other for 12 seconds. Both subprocesses executed thegetrandomcall at the same time, precisely at 1701835831 seconds. Thisgetrandomcall originates from therandom.pymodule.This indicates that the code is blocking in
PyOS_AfterFork_Child()and not in the business logic code.The captured
straceresults are as follows:child process 1：
child process 2:
CPython versions tested on:
3.9
Operating systems tested on:
Linux