| *** motto has joined #zope | 00:20 | |
| *** kosh has joined #zope | 00:22 | |
| *** m8 has quit IRC | 00:22 | |
| *** J1m has quit IRC | 00:30 | |
| *** roq_ has joined #zope | 01:05 | |
| *** thetet has quit IRC | 01:19 | |
| *** Arfrever has joined #zope | 01:22 | |
| *** motto has quit IRC | 01:33 | |
| *** TresEquis has quit IRC | 01:40 | |
| *** mcdonc has quit IRC | 01:40 | |
| *** mcdonc has joined #zope | 01:41 | |
| *** sp0cksbeard has quit IRC | 01:45 | |
| *** supton_ has joined #zope | 01:48 | |
| *** supton has quit IRC | 01:51 | |
| *** fdrake has quit IRC | 02:00 | |
| *** roq_ has quit IRC | 02:13 | |
| *** J1m has joined #zope | 02:32 | |
| *** dayne has joined #zope | 02:49 | |
| *** runyaga has quit IRC | 02:56 | |
| *** _mup_ has quit IRC | 03:00 | |
| *** _mup_ has joined #zope | 03:00 | |
| *** Spanktar has quit IRC | 03:11 | |
| *** J1m has quit IRC | 03:27 | |
| *** tiwula has quit IRC | 03:30 | |
| *** CIA-101 has quit IRC | 03:42 | |
| *** CIA-101 has joined #zope | 04:12 | |
| *** fdrake has joined #zope | 04:37 | |
| *** daMaestro has quit IRC | 05:02 | |
| *** kosh has quit IRC | 05:11 | |
| *** KageSenshi has quit IRC | 07:22 | |
| *** walden_ has joined #zope | 07:32 | |
| *** Deichi has joined #zope | 08:37 | |
| *** nande has quit IRC | 08:44 | |
| *** KageSenshi has joined #zope | 08:46 | |
| *** yvl has joined #zope | 08:50 | |
| *** agroszer has joined #zope | 09:07 | |
| *** tomas has left #zope | 09:12 | |
| *** __mac__ has joined #zope | 09:21 | |
| *** MrTango has joined #zope | 09:36 | |
| *** mitchell`off is now known as mitchell` | 09:39 | |
| *** tisto has joined #zope | 09:41 | |
| *** avoinea has joined #zope | 09:46 | |
| *** giacomos has joined #zope | 10:06 | |
| *** walden_ has quit IRC | 10:08 | |
| *** fredvd has joined #zope | 10:15 | |
| *** fredvd2 has joined #zope | 10:17 | |
| *** fredvd has quit IRC | 10:17 | |
| *** fredvd2 has quit IRC | 10:45 | |
| *** eperez has joined #zope | 10:46 | |
| *** fredvd has joined #zope | 11:45 | |
| *** evilbungle has joined #zope | 12:07 | |
| *** RichyB has joined #zope | 12:11 | |
| *** maurits has joined #zope | 12:13 | |
| *** goschtl has joined #zope | 12:27 | |
| *** teix has joined #zope | 13:06 | |
| *** Zart has left #zope | 13:14 | |
| *** fdrake has quit IRC | 13:22 | |
| *** zagy has joined #zope | 13:39 | |
| *** tisto has quit IRC | 13:47 | |
| *** tisto_ has joined #zope | 13:47 | |
| *** J1m has joined #zope | 14:08 | |
| *** RichyB has quit IRC | 14:09 | |
| *** thetet has joined #zope | 14:12 | |
| *** tisto_ is now known as tisto|lunch | 14:15 | |
| *** kosh has joined #zope | 14:17 | |
| *** M46IST has joined #zope | 14:21 | |
| *** RichyB has joined #zope | 14:22 | |
| *** RichyB has quit IRC | 14:27 | |
| *** RichyB has joined #zope | 14:28 | |
| *** J1m has quit IRC | 14:40 | |
| *** evilbungle has quit IRC | 14:41 | |
| *** evilbungle_ has joined #zope | 14:41 | |
| *** goschtl has quit IRC | 14:47 | |
| *** goschtl has joined #zope | 14:48 | |
| *** fdrake has joined #zope | 14:49 | |
| *** deuterium has joined #zope | 15:19 | |
| deuterium | re | 15:19 |
|---|---|---|
| deuterium | when attaching gdb to the python instance that runs my zope and if i do a "info threads" afterwards, all but two threads are in state sem_wait (). is this to be expected? see http://dpaste.com/799387/ | 15:24 |
| deuterium | thing is that i observe a constantly high cpu load (100%) of the python process running zope, for no obvious reason. | 15:25 |
| mgedmin | yeah, waiting for a semaphore sounds right | 15:26 |
| mgedmin | if you can hack your zope to provide Python tracebacks of all the threads (using sys._currentframes().values() and traceback.print_stack(f)), that would be more useful than C level stacks | 15:27 |
| mgedmin | it should be easily doable from an external method | 15:27 |
| deuterium | mgedmin: i tried to use call PyRun_SimpleString("import sys, traceback; sys.stderr=open('/tmp/tb','w',0); traceback.print_stack()") from within gdb, but i didn't know which thread i should select | 15:30 |
| mgedmin | "all of them" would be a good start ;) | 15:31 |
| deuterium | so i didn't do it. but that would print a python traceback, according to http://old.zope.org/Members/4am/debugspinningzope | 15:31 |
| deuterium | mgedmin: hm.. how can i select all? ;) | 15:31 |
| mgedmin | change 'traceback.print_stack()' in that example to 'for f in sys._currentframes().values(): traceback.print_stack(f)' | 15:32 |
| mgedmin | NB: not tested | 15:32 |
| mgedmin | let me try it out now | 15:32 |
| mgedmin | hm, I'm getting a syntax error | 15:33 |
| deuterium | hm | 15:33 |
| mgedmin | import sys, traceback; sys.stderr = open('/tmp/tb', 'w', 0); [traceback.print_stack(f) for f in sys._current_frames().values()] | 15:34 |
| mgedmin | works as a one-liner | 15:34 |
| deuterium | ok, nice :) i try this | 15:34 |
| mgedmin | also, you may want to restart that Zope instance at some point, as that oneline you ran permanently leaves sys.stderr redirected to that /tmp file | 15:34 |
| deuterium | the thing which somewhat confuses me regarding sem_wait is that man 3 sem_wait states: "If the semaphore's value is greater than zero, then the decrement proceeds, and the function | 15:35 |
| deuterium | returns, immediately. If the semaphore currently has the value zero, then the call blocks until either it becomes possible to perform the decrement (i.e., the | 15:35 |
| deuterium | semaphore value rises above zero), or a signal handler interrupts the call." | 15:35 |
| mgedmin | a better one-liner would be | 15:35 |
| deuterium | oops, sorry | 15:35 |
| mgedmin | import sys, traceback; tmpf = open('/tmp/tb', 'w', 0); [traceback.print_stack(f, file=tmpf) for f in sys._current_frames().values()] | 15:35 |
| deuterium | ok, let me try this | 15:36 |
| mgedmin | or even | 15:36 |
| mgedmin | import sys, traceback; tmpf = open('/tmp/tb', 'w', 0); [(traceback.print_stack(f, file=tmpf), tmpf.write('---\n')) for f in sys._current_frames().values()] | 15:36 |
| mgedmin | [(None, None)] | 15:36 |
| mgedmin | so you can more easily see where each traceback begins and ends | 15:36 |
| betabug | I would try the DeadlockDebugger | 15:37 |
| mgedmin | using gdb + PyRun_SimpleString is a nice trick | 15:37 |
| betabug | why reinvent the wheel? it should run on 2.8 too | 15:37 |
| deuterium | betabug: http://old.zope.org/Members/nuxeo/Products/DeadlockDebugger/ ? | 15:39 |
| deuterium | betabug: would need to be installed separately, right? can't find it in apt-cache | 15:40 |
| betabug | yes, looks like that is the one | 15:40 |
| betabug | you put it into the "Products" folder in the instance | 15:40 |
| mgedmin | in the meantime, pastebin the tracebacks you've already gotten? | 15:40 |
| betabug | and you have to edit one file inside it (there are instructions) | 15:40 |
| deuterium | betabug: i'm first trying mgedmin's one-liner | 15:40 |
| betabug | sure | 15:40 |
| mgedmin | oh, I thought you already tried that :) | 15:40 |
| *** sunew has joined #zope | 15:41 | |
| deuterium | mgedmin: well, it's a live system.. i'm very cautious i don't accidentally destroy anything | 15:41 |
| mgedmin | yeah... every time I tried to introspect a running Python process with gdb, I managed to make it segfault | 15:42 |
| betabug | deuterium: so that fake "bing" request wasn't the cause of the high load? | 15:44 |
| deuterium | betabug: well, i can't rule this out yet.. i have to block "bingbot" requests on the box using fail2ban indeed.. but actually we filter things on a dedicated firewall and also use a proxy.. unfortunately it can be bypassed, so i have to temporarily filter out the requests on the zope box itself | 15:47 |
| deuterium | mgedmin: (gdb) call PyRun_SimpleString("import sys, traceback; tmpf = open('/tmp/tb', 'w', 0); [(traceback.print_stack(f, file=tmpf), tmpf.write('---\n')) for f in sys._current_frames().values()] [(None, None)]") | 15:48 |
| deuterium | $1 = -1 | 15:48 |
| deuterium | mgedmin: without selecting a particular thread first (maybe i need to do this?) | 15:48 |
| deuterium | but i don't know which thread to select | 15:49 |
| deuterium | one actually seems to be in select () state already | 15:49 |
| deuterium | hm.. if i issue a "select 1" first (it's the thread that uses 100% cpu), there's the same error with that one-liner.. must be a typo or syntax error or so, i guess? | 15:50 |
| deuterium | i.e. there's no /tmp/tb created | 15:51 |
| *** menesis1 has joined #zope | 15:52 | |
| deuterium | this one works: | 15:53 |
| deuterium | call PyRun_SimpleString("import sys, traceback; tmpf = open('/tmp/tb', 'w', 0); [traceback.print_stack(f, file=tmpf) for f in sys._current_frames().values()]") | 15:53 |
| deuterium | :) | 15:53 |
| deuterium | hm.. tb is empty though | 15:54 |
| deuterium | maybe i need to tell gdb to continue with executing the thread? | 15:54 |
| deuterium | ah nice, the original one-liner works fine without an error and fills the /tmp/tb file: | 15:57 |
| deuterium | call PyRun_SimpleString("import sys, traceback; sys.stderr=open('/tmp/tb','w',0); traceback.print_stack()") | 15:57 |
| mgedmin | which Python? | 16:03 |
| mgedmin | i.e. which Python version do you have? | 16:03 |
| mgedmin | sys._current_frames() appeared in 2.5 | 16:04 |
| *** les_sylvains has joined #zope | 16:04 | |
| *** RichyB has quit IRC | 16:05 | |
| *** kosh has quit IRC | 16:06 | |
| *** J1m has joined #zope | 16:10 | |
| deuterium | mgedmin: python 2.3.6 | 16:11 |
| mgedmin | yeah... | 16:11 |
| deuterium | and here's the traceback from /tmp/tb with the original one-liner: http://dpaste.com/799406/ | 16:12 |
| deuterium | i've no idea whether there's any indication of a high cpu load in this traceback? | 16:13 |
| mgedmin | hard to say, it looks like a normal transaction commit | 16:13 |
| mgedmin | how many requests per second is the server handling? | 16:13 |
| deuterium | in the instance logs, i strangely see requests from (alleged, perhaps) search bots only.. like "bingbot", Googlebot etc. at about 1 request per second. cpu load is 100% | 16:14 |
| deuterium | should i try the http://old.zope.org/Members/nuxeo/Products/DeadlockDebugger/ first or rather try blocking the "bingbot" etc. requests? | 16:24 |
| deuterium | betabug: is the deadlockdebugger useful to find out which threads create the 100% cpu load? | 16:24 |
| betabug | I would think so | 16:25 |
| deuterium | ok, i try this | 16:25 |
| betabug | in my experience you want to block that fake bot in any case | 16:26 |
| deuterium | hm.. there's no documentation though and the deadlockdebugger is from 2005 | 16:26 |
| deuterium | betabug: ok, i'll try that first.. using fail2ban locally on the zope server | 16:26 |
| betabug | deuterium: your zope isn't any newer | 16:27 |
| betabug | the documentation is in the REQDME.txt IIRC | 16:27 |
| betabug | s/Q/A/ | 16:27 |
| betabug | deuterium: also maybe did you try running a copy of the site on another host and see if that goes to 100% too? | 16:28 |
| mgedmin | maybe block all HTTP requests for 10 minutes, see if the load drops to 0? | 16:29 |
| deuterium | betabug: already migrated the whole server from a physical server to a (now) virtual server, but the high cpu load remained, thought the whole hardware below should allow for double the performance, all in all. | 16:30 |
| mgedmin | I see that DeadlockDebugger depends on http://pypi.python.org/pypi/threadframe | 16:30 |
| betabug | yeah, what mgedmin said then... or make a copy of the vm and try it there first | 16:30 |
| deuterium | betabug: i thus really thing there's something with that zope instance.. or it might be a disguised attack indeed | 16:30 |
| betabug | yeah | 16:30 |
| mgedmin | so it should work on your ancient Python | 16:30 |
| *** RichyB has joined #zope | 16:31 | |
| deuterium | mgedmin: ok | 16:31 |
| deuterium | i'm trying to block the *bots | 16:31 |
| betabug | I have some experience with DeadlockDebugger, it helped me solve some problem with another old zope a year ago | 16:31 |
| *** evilbungle_ has quit IRC | 16:35 | |
| *** evilbungle has joined #zope | 16:36 | |
| *** sp0cksbeard has joined #zope | 16:41 | |
| *** evilbungle_ has joined #zope | 16:41 | |
| *** evilbungle has quit IRC | 16:42 | |
| *** evilbungle_ is now known as evilbungle | 16:42 | |
| *** roq_ has joined #zope | 16:42 | |
| deuterium | i'm currently writing the fail2ban rule for blocking the bots | 16:50 |
| deuterium | according to the zope instance's log, there are currently quite a few "normal" requests to be handled as well.. i'd say about 3-6 per second. justifies 100% cpu load? | 16:51 |
| *** les_sylvains has left #zope | 16:52 | |
| mgedmin | maybe | 16:52 |
| deuterium | hm | 16:53 |
| *** menesis1 has quit IRC | 16:55 | |
| betabug | no, I think there is something fishy | 16:57 |
| betabug | maybe it's looking for some external resource or so | 16:57 |
| betabug | I'd look at how long these requests take | 16:57 |
| betabug | and at the profiler in the Control_panel, maybe you can spot what they are doing there | 16:58 |
| betabug | anyway, I'm off for a swim now, good luck for the moment :-) | 16:58 |
| *** menesis has joined #zope | 17:02 | |
| *** goschtl has quit IRC | 17:02 | |
| deuterium | betabug: ok, thanks a lot for the hint! have a nice swim (outdoor baths are mostly closed in zurich already ;) | 17:03 |
| *** Deichi has quit IRC | 17:04 | |
| *** dayne has quit IRC | 17:11 | |
| *** thetet has quit IRC | 17:19 | |
| *** menesis has quit IRC | 17:27 | |
| *** menesis has joined #zope | 17:27 | |
| deuterium | i just wonder, where the profile is in the control panel? maybe /Control_Panel/DebugInfo? /cc mgedmin | 17:37 |
| mgedmin | eh, I dunno | 17:38 |
| mgedmin | you should /cc betabug on this | 17:38 |
| deuterium | mgedmin: he's off swimming, lol | 17:38 |
| * deuterium should actually do this too.. it's the last warm day in .ch ;) | 17:39 | |
| deuterium | mgedmin: "Top Refcounts" is the number of calls to that function? | 17:39 |
| mgedmin | no, that looks like memory usage stats | 17:40 |
| deuterium | hm.. can't find any information there about long-running or cpu intensive threads (or requests) | 17:41 |
| mgedmin | have you installed DeadlockDebugger yet? | 17:41 |
| deuterium | ah lol, i found the profiler.. it's simply the other tab there | 17:42 |
| deuterium | "Profiling is not currently enabled or there is not yet any profiling data to report. To enable profiling, restart the Zope process with the configuration setting 'publisher-profile-file' defined. The value of this variable should be the full system path to a file that will be used to dump a profile report when the process restarts or exits." | 17:42 |
| deuterium | mgedmin: no, haven't installed it yet | 17:42 |
| deuterium | i think i'll try the profiler first | 17:43 |
| *** __mac__ has quit IRC | 17:49 | |
| deuterium | "In order to use profiling Zope has to be started with the PROFILE_PUBLISHER environment variable set to a non-empty value." | 17:50 |
| deuterium | mgedmin: is this a normal system environment variable that i can set simply before starting zope? | 17:50 |
| *** daMaestro has joined #zope | 17:51 | |
| mgedmin | yeah | 17:51 |
| mgedmin | I wonder what negative side effects it has... | 17:51 |
| * mgedmin never used the Zope 2 profiler | 17:51 | |
| deuterium | slows down the system temporarily | 17:51 |
| deuterium | i.e. zope, i meant | 17:52 |
| mgedmin | all of the requests, or just while you have profiling enabled? | 17:52 |
| deuterium | btw, looks like it can also be set in <environment></environment> | 17:52 |
| deuterium | while having it enabled | 17:52 |
| deuterium | but a restart seems to be required | 17:52 |
| *** sunew has quit IRC | 18:02 | |
| *** nande has joined #zope | 18:03 | |
| deuterium | hm.. strangely, the profiling tab in zmi doesn't show any information, though i've defined PROFILE_PUBLISHER /var/lib/zope/instance/elk9/log/profiler.log in the conf files <environment></environment> | 18:12 |
| *** zagy has quit IRC | 18:27 | |
| deuterium | enabling the profiler simply doesn't work.. there's no information displayed neither in the tab nor is there any log file created | 18:28 |
| deuterium | i've also defined an according system var, doesn't have any effect upon restarting zope either | 18:28 |
| *** tisto|lunch has quit IRC | 18:40 | |
| *** agroszer has quit IRC | 18:41 | |
| *** alecm has quit IRC | 18:44 | |
| *** alecm has joined #zope | 18:49 | |
| *** supton has joined #zope | 18:49 | |
| *** giacomos has quit IRC | 19:13 | |
| *** maurits has quit IRC | 19:14 | |
| *** fredvd has quit IRC | 19:16 | |
| *** fredvd has joined #zope | 19:16 | |
| *** fredvd has quit IRC | 19:21 | |
| betabug | back | 19:24 |
| betabug | deuterium: dunno about the profiler | 19:24 |
| betabug | I thought it was easy to enable, but can't remember how I did it | 19:25 |
| deuterium | betabug: hm.. it's supposed to be easy to enable.. just set an environment var. or set it in the zope.conf file. unfortunately, that didn't work though. | 19:26 |
| betabug | weird | 19:26 |
| deuterium | it's strange, yes | 19:26 |
| betabug | as for swimming, it was a bit cool in the sea, as we were a bit late :-) | 19:26 |
| deuterium | well, i have to continue debugging this later | 19:26 |
| deuterium | you were in the sea? ;) | 19:27 |
| deuterium | i guess lake, right? | 19:27 |
| deuterium | lake of zurich? | 19:27 |
| betabug | I'm in .gr | 19:27 |
| deuterium | oh my | 19:27 |
| deuterium | that's nice for sure | 19:27 |
| betabug | on Naxos right now - but I'm actually from .ch myself | 19:27 |
| deuterium | how many degrees? | 19:27 |
| betabug | dunno the temperature | 19:27 |
| betabug | I'm still running around in shorts, but in the evenigs I started to put on a shirt | 19:28 |
| deuterium | still much warmer than here, i guess.. water temp is around 20 °C only, afaik | 19:28 |
| betabug | 20c would be pretty good for Zuerich | 19:29 |
| deuterium | ok.. i should go on vacation too.. should go more southwards then, i guess.. egypt, maybe | 19:29 |
| betabug | depends if you still want to go to swim, yes | 19:29 |
| betabug | here at the end of the month I think the swimming will be over | 19:29 |
| * deuterium hasn't had any summer vacation yet | 19:29 | |
| deuterium | oh ok | 19:30 |
| deuterium | well, enjoy it, then! | 19:30 |
| *** Spanktar has joined #zope | 19:31 | |
| *** Spanktar has joined #zope | 19:32 | |
| betabug | well, I didn't have any summer vacatioin yet either, but I managed to go for swims some times after work :-) | 19:32 |
| deuterium | thanks mgedmin & betabug! bbl | 19:38 |
| *** deuterium has quit IRC | 19:42 | |
| *** m8 has joined #zope | 19:53 | |
| *** menesis has quit IRC | 19:59 | |
| *** MrTango has quit IRC | 20:04 | |
| *** evilbungle_ has joined #zope | 20:06 | |
| *** agroszer has joined #zope | 20:06 | |
| *** evilbungle has quit IRC | 20:10 | |
| *** evilbungle_ is now known as evilbungle | 20:10 | |
| *** deuterium has joined #zope | 20:12 | |
| *** zenwryly has quit IRC | 20:18 | |
| *** zenwryly has joined #zope | 20:19 | |
| *** avoinea has quit IRC | 20:22 | |
| *** eperez has quit IRC | 20:31 | |
| *** zenwryly has quit IRC | 20:38 | |
| *** zenwryly has joined #zope | 20:39 | |
| *** menesis has joined #zope | 20:44 | |
| *** evilbungle has quit IRC | 20:45 | |
| *** tiwula has joined #zope | 20:49 | |
| *** agroszer has quit IRC | 20:54 | |
| *** zenwryly has quit IRC | 20:57 | |
| *** zenwryly has joined #zope | 20:57 | |
| *** RichyB has quit IRC | 21:14 | |
| *** mitchell` is now known as mitchell`off | 21:15 | |
| *** zenwryly has quit IRC | 21:17 | |
| *** zenwryly has joined #zope | 21:17 | |
| *** kosh has joined #zope | 21:31 | |
| *** tiwula has quit IRC | 21:32 | |
| *** tiwula has joined #zope | 21:50 | |
| *** teix has quit IRC | 21:57 | |
| *** polysix has quit IRC | 21:57 | |
| *** mgedmin has quit IRC | 21:57 | |
| *** teix has joined #zope | 21:58 | |
| *** polysix has joined #zope | 21:58 | |
| *** mgedmin has joined #zope | 21:58 | |
| *** polysix has quit IRC | 21:59 | |
| *** polysix has joined #zope | 21:59 | |
| *** KageSenshi has quit IRC | 22:05 | |
| *** teix has quit IRC | 22:38 | |
| *** nande has quit IRC | 22:45 | |
| *** M46IST has left #zope | 22:56 | |
| *** menesis has quit IRC | 23:22 | |
| *** m8 has quit IRC | 23:34 | |
| *** supton_ has joined #zope | 23:50 | |
| *** supton_ has quit IRC | 23:50 | |
| *** supton has quit IRC | 23:54 | |
Generated by irclog2html.py 2.15.1 by Marius Gedminas - find it at mg.pov.lt!