Update: Sorry deadlock prevention seems to working too. But not always: Why request with pid:13443 did not managed to get lock? Master not yet collected dead children?
2012-02-02 13:30:16,918 DEBUG 13441 pid: 13441 going to lock 2012-02-02 13:30:22,238 DEBUG 13437 pid: 13437 going again to sleep: 5.70 *** HARAKIRI ON WORKER 1 (pid: 13441) *** HARAKIRI: -- syscall> 202 0x7f0481a080a0 0x0 0x2 0x0 0x7f0481a080a0 0x3481 0x7fffc5af0a30 0x7f04815db7c4 HARAKIRI: -- wchan> futex_wait_queue_me HARAKIRI: --- uWSGI worker 1 (pid: 13441) WAS managing request /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:30:11 2012 --- *** HARAKIRI ON WORKER 2 (pid: 13437) *** HARAKIRI: -- syscall> 23 0x0 0x0 0x0 0x0 0x7fffc5af0a40 0x4014000000000000 0x7fffc5aef5e0 0x7f047fd74123 HARAKIRI: -- wchan> poll_schedule_timeout HARAKIRI: --- uWSGI worker 2 (pid: 13437) WAS managing request /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:30:11 2012 --- 2012-02-02 13:30:23,932 DEBUG 13437 pid: 13437 going to UNlock 2012-02-02 13:30:23,932 DEBUG 13437 pid: 13437 going to lock 2012-02-02 13:30:23,932 DEBUG 13437 pid: 13437 locked aquire time: 0.000129. 2012-02-02 13:30:23,932 DEBUG 13437 pid: 13437 going to sleep: 9.53 DAMN ! worker 2 (pid: 13437) died :( trying respawn ... Respawned uWSGI worker 2 (new pid: 13442) DAMN ! worker 1 (pid: 13441) died :( trying respawn ... Respawned uWSGI worker 1 (new pid: 13443) 2012-02-02 13:30:55,593 DEBUG 13443 pid: 13443 request started 2012-02-02 13:31:00,600 DEBUG 13443 pid: 13443 going to lock *** HARAKIRI ON WORKER 1 (pid: 13443) *** HARAKIRI: -- syscall> 202 0x7f0481a080a0 0x0 0x2 0x0 0x7f0481a080a0 0x3483 0x7fffc5af0a30 0x7f04815db7c4 HARAKIRI: -- wchan> futex_wait_queue_me HARAKIRI: --- uWSGI worker 1 (pid: 13443) WAS managing request /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:30:55 2012 --- DAMN ! worker 1 (pid: 13443) died :( trying respawn ... Respawned uWSGI worker 1 (new pid: 13445) 2012-02-02 13:31:16,629 DEBUG 13445 pid: 13445 request started 2012-02-02 13:31:21,632 DEBUG 13445 pid: 13445 going to lock 2012-02-02 13:31:21,633 DEBUG 13445 pid: 13445 locked aquire time: 0.000343. 2012-02-02 13:31:21,633 DEBUG 13445 pid: 13445 going to sleep: 2.03 2012-02-02 13:31:23,669 DEBUG 13445 pid: 13445 going again to sleep: 2.03 2012-02-02 13:31:25,706 DEBUG 13445 pid: 13445 going to UNlock 2012-02-02 13:31:25,706 DEBUG 13445 pid: 13445 going to lock 2012-02-02 13:31:25,706 DEBUG 13445 pid: 13445 locked aquire time: 0.000133. 2012-02-02 13:31:25,706 DEBUG 13445 pid: 13445 going to sleep: 4.74 *** HARAKIRI ON WORKER 1 (pid: 13445) *** HARAKIRI: -- syscall> 23 0x0 0x0 0x0 0x0 0x7fffc5af0a40 0x4010000000000000 0x7fffc5af0a38 0x7f047fd74123 HARAKIRI: -- wchan> poll_schedule_timeout HARAKIRI: --- uWSGI worker 1 (pid: 13445) WAS managing request /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:31:16 2012 --- 2012-02-02 13:31:27,994 DEBUG 13445 pid: 13445 going again to sleep: 4.74 DAMN ! worker 1 (pid: 13445) died :( trying respawn ... Respawned uWSGI worker 1 (new pid: 13446) 2012-02-02 13:32:00,001 DEBUG 13442 pid: 13442 request started 2012-02-02 13:32:05,006 DEBUG 13442 pid: 13442 going to lock 2012-02-02 13:32:05,007 DEBUG 13442 pid: 13442 locked aquire time: 0.000336. 2012-02-02 13:32:05,007 DEBUG 13442 pid: 13442 going to sleep: 6.55 *** HARAKIRI ON WORKER 2 (pid: 13442) *** HARAKIRI: -- syscall> 23 0x0 0x0 0x0 0x0 0x7fffc5af0a40 0x4018000000000000 0x7fffc5af0a08 0x7f047fd74123 HARAKIRI: -- wchan> poll_schedule_timeout HARAKIRI: --- uWSGI worker 2 (pid: 13442) WAS managing request /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:32:00 2012 --- 2012-02-02 13:32:10,034 DEBUG 13442 pid: 13442 going again to sleep: 6.55 DAMN ! worker 2 (pid: 13442) died :( trying respawn ... Respawned uWSGI worker 2 (new pid: 13448) 2012/2/2 Evgeny Turnaev <[email protected]>: > Locking is working. Deadlock prevention not. > 1.1-dev-1910 > > > 2012-02-02 13:22:56,643 DEBUG 13388 pid: 13388 request started > 2012-02-02 13:22:57,037 DEBUG 13387 pid: 13387 request started > 2012-02-02 13:23:01,649 DEBUG 13388 pid: 13388 going to lock > 2012-02-02 13:23:01,649 DEBUG 13388 pid: 13388 locked aquire time: 0.000332. > 2012-02-02 13:23:01,649 DEBUG 13388 pid: 13388 going to sleep: 2.33 > 2012-02-02 13:23:02,043 DEBUG 13387 pid: 13387 going to lock > 2012-02-02 13:23:03,978 DEBUG 13388 pid: 13388 going again to sleep: 2.33 > 2012-02-02 13:23:06,308 DEBUG 13388 pid: 13388 going to UNlock > 2012-02-02 13:23:06,308 DEBUG 13388 pid: 13388 going to lock > 2012-02-02 13:23:06,308 DEBUG 13387 pid: 13387 locked aquire time: 4.265560. > 2012-02-02 13:23:06,309 DEBUG 13387 pid: 13387 going to sleep: 0.06 > 2012-02-02 13:23:06,367 DEBUG 13387 pid: 13387 going again to sleep: 0.06 > 2012-02-02 13:23:06,426 DEBUG 13387 pid: 13387 going to UNlock > 2012-02-02 13:23:06,427 DEBUG 13387 pid: 13387 going to lock > 2012-02-02 13:23:06,427 DEBUG 13388 pid: 13388 locked aquire time: 0.118412. > 2012-02-02 13:23:06,427 DEBUG 13388 pid: 13388 going to sleep: 8.01 > *** HARAKIRI ON WORKER 2 (pid: 13388) *** > HARAKIRI: -- syscall> 23 0x0 0x0 0x0 0x0 0x7fffe2ef7ca0 > 0x4020000000000000 0x7fffe2ef7c98 0x7fadfb7c3123 > HARAKIRI: -- wchan> poll_schedule_timeout > HARAKIRI: --- uWSGI worker 2 (pid: 13388) WAS managing request > /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:22:56 > 2012 --- > 2012-02-02 13:23:07,397 DEBUG 13388 pid: 13388 going again to sleep: 8.01 > *** HARAKIRI ON WORKER 1 (pid: 13387) *** > HARAKIRI: -- syscall> 202 0x7fadfd4570a0 0x0 0x2 0x0 0x7fadfd4570a0 > 0x344b 0x7fffe2ef7c98 0x7fadfd02a7c4 > HARAKIRI: -- wchan> futex_wait_queue_me > HARAKIRI: --- uWSGI worker 1 (pid: 13387) WAS managing request > /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:22:57 > 2012 --- > DAMN ! worker 2 (pid: 13388) died :( trying respawn ... > Respawned uWSGI worker 2 (new pid: 13390) > DAMN ! worker 1 (pid: 13387) died :( trying respawn ... > Respawned uWSGI worker 1 (new pid: 13391) > > > > 2012-02-02 13:24:28,786 DEBUG 13390 pid: 13390 request started > 2012-02-02 13:24:29,105 DEBUG 13391 pid: 13391 request started > 2012-02-02 13:24:33,791 DEBUG 13390 pid: 13390 going to lock > 2012-02-02 13:24:34,111 DEBUG 13391 pid: 13391 going to lock > *** HARAKIRI ON WORKER 2 (pid: 13390) *** > HARAKIRI: -- syscall> 202 0x7fadfd4570a0 0x0 0x2 0x0 0x7fadfd4570a0 > 0x344e 0x7fffe2ef7c90 0x7fadfd02a7c4 > HARAKIRI: -- wchan> futex_wait_queue_me > HARAKIRI: --- uWSGI worker 2 (pid: 13390) WAS managing request > /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:24:28 > 2012 --- > *** HARAKIRI ON WORKER 1 (pid: 13391) *** > HARAKIRI: -- syscall> 202 0x7fadfd4570a0 0x0 0x2 0x0 0x7fadfd4570a0 > 0x344f 0x7fffe2ef7c90 0x7fadfd02a7c4 > HARAKIRI: -- wchan> futex_wait_queue_me > HARAKIRI: --- uWSGI worker 1 (pid: 13391) WAS managing request > /serp?query=%D0%BF%D1%83%D1%82%D0%B8%D0%BD since Thu Feb 2 13:24:29 > 2012 --- > DAMN ! worker 2 (pid: 13390) died :( trying respawn ... > Respawned uWSGI worker 2 (new pid: 13393) > DAMN ! worker 1 (pid: 13391) died :( trying respawn ... > Respawned uWSGI worker 1 (new pid: 13394) > > > ------------ > def do_lock_thing(): > start_time = time.time() > debug("pid: %s going to lock" % os.getpid()) > uwsgi.lock() > debug("pid: %s locked aquire time: %0.6f." % (os.getpid(), > time.time() - start_time)) > sleep_time = random.random() * 10 > debug("pid: %s going to sleep: %0.2f" % (os.getpid(), sleep_time)) > time.sleep(sleep_time) > debug("pid: %s going again to sleep: %0.2f" % (os.getpid(), sleep_time)) > time.sleep(sleep_time) > debug("pid: %s going to UNlock" % os.getpid()) > uwsgi.unlock() > > def application(environ, start_response): > headers = [ > ('Content-Type', 'text/html'), > ] > write = start_response('200 OK', headers) > debug("pid: %s request started" % os.getpid()) > time.sleep(5) > for x in range(2): > do_lock_thing() > yield 'Hello World' > debug("pid: %s end of application.." % os.getpid()) > > > > 2012/2/2 Roberto De Ioris <[email protected]>: >> >>> Whoa! That's really a nice and elegant solution of deadlock preventions. >>> Hmm something went wrong. >>> 1.1-dev-1906 >>> >>> >> >> >> Should be fixed now (both) >> >> >>> Another thing to note: i still think continuing request execution >>> after usr2 is a bug. It is better to exit(1) in usr2 handler in >>> worker. I think it is better to make harakiri 2 step: 1) usr2 is sent >>> to worker and master marks pid as harakiri first step. A worker should >>> do exit(1) when receives usr2. This will make sleep(1) and kill(kill) >>> unnessessary in 99% cases. Also removing 1 sec delay in possible lock >>> deadlock. 2) Master should periodically check for harakiki pids and if >>> it is in harakiki state for > 1 sec kill(kill) it. Never-less >>> continuing request handler after usr2 is a bug. >>> >> >> This would require a bit of refactoring as USR2 is not only used by >> harakiri, but in general i am not against it. >> >> >> -- >> Roberto De Ioris >> http://unbit.it >> _______________________________________________ >> uWSGI mailing list >> [email protected] >> http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi > > > > -- > -------------------------------------------- > Турнаев Евгений Викторович > +7 906 875 09 43 > -------------------------------------------- -- -------------------------------------------- Турнаев Евгений Викторович +7 906 875 09 43 -------------------------------------------- _______________________________________________ uWSGI mailing list [email protected] http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi
