| 00:31.19 | *** join/#asterisk-dev pchero (~pchero@x1-6-d8-d7-75-5e-99-79.cpe.webspeed.dk) |
| 00:38.08 | *** join/#asterisk-dev pchero (~pchero@x1-6-d8-d7-75-5e-99-79.cpe.webspeed.dk) |
| 01:24.24 | *** join/#asterisk-dev infobot (ibot@rikers.org) |
| 01:24.24 | *** topic/#asterisk-dev is Asterisk Development Discussion -=- http://www.asterisk.org/developers -=- Tier 2 and 3.14159265 support is in #asterisk -=- Check out our blog! blogs.asterisk.org -=- Follow on Twitter at @AsteriskDev |
| 02:30.01 | *** join/#asterisk-dev leedm777 (~textual@2604:2d80:8404:ffae:570:c8a3:54d3:ae8d) |
| 02:30.01 | *** mode/#asterisk-dev [+o leedm777] by ChanServ |
| 03:01.38 | *** join/#asterisk-dev Oooohboy (~Oooohboy@2605:6000:1711:c1ff:6548:8903:3d10:36fa) |
| 03:14.35 | *** join/#asterisk-dev leedm777 (~textual@2604:2d80:8404:ffae:8de1:5816:f626:6d2e) |
| 03:14.35 | *** mode/#asterisk-dev [+o leedm777] by ChanServ |
| 03:29.56 | *** join/#asterisk-dev gtjoseph (~gtjoseph@unaffiliated/gtj) |
| 03:29.56 | *** mode/#asterisk-dev [+o gtjoseph] by ChanServ |
| 05:02.15 | *** join/#asterisk-dev leedm777 (~textual@2604:2d80:8404:ffae:f5c7:c073:f33e:5cb9) |
| 05:02.15 | *** mode/#asterisk-dev [+o leedm777] by ChanServ |
| 07:47.23 | *** join/#asterisk-dev tsearle (~tsearle@37.19.10.33) |
| 07:47.23 | *** mode/#asterisk-dev [+o tsearle] by ChanServ |
| 08:06.12 | *** join/#asterisk-dev tzafrir (~tzafrir@local.xorcom.com) |
| 08:06.12 | *** mode/#asterisk-dev [+o tzafrir] by ChanServ |
| 09:16.34 | *** join/#asterisk-dev tsearle_ (~tsearle@37.19.10.33) |
| 09:16.34 | *** mode/#asterisk-dev [+o tsearle_] by ChanServ |
| 11:53.39 | jkroon | what is the purpose of the manager event queue? as I can see it forms a circular buffer where connected AMI sessions (assuming that no CLI entry is being processed) can use to buffer Events that needs to be queued. |
| 11:54.39 | jkroon | i've run into some odd cases now where I get a lot of threads stuck in append_event(), some presumably with a lock on ast_channel structures, resulting in system deadlock. |
| 11:58.55 | jkroon | so what i suspect is that for some reason the Command event in some cases takes up way too much time (i've seen file convert's stall for days, presumably due to a bug in the encoder/decoder somewhere which i'll chase down later) |
| 11:59.43 | jkroon | eventually core show channels too fails, and this I'm guessing is due to append_event stalling for some reason. |
| 12:35.42 | coreyfarrell | jkroon: at minimum it's needed for manager over HTTP. I'm not sure why append_event would get stuck, from what I can tell nothing is locked after all_events is locked. |
| 12:36.14 | jkroon | coreyfarrell, according to the stack traces i've got that is what's getting stuck. |
| 12:36.40 | coreyfarrell | it's possible that running CLI 'manager show eventq' a lot could slow things down. |
| 12:37.06 | jkroon | my current (only possible working theory) is that something somewhere else has a lock which prevents the write-lock in append_event from taking the lock. |
| 12:37.15 | jkroon | i only discovered that command now whilst trying to debug the problem. |
| 12:42.07 | coreyfarrell | you can search manager.c for all references to all_events - only a few functions lock that structure and the lock is only held for minimum time. I'm guessing you'll need DEBUG_THREADS to troubleshoot further. |
| 12:42.44 | jkroon | and that would (even at x2 CPU) kill the affected server. going to see if I can reproduce another way, but your assessment concurs with mine. |
| 12:49.17 | coreyfarrell | possible something is hammering grab_last or advance_event. maybe you could use ast_log to add tracer messages to those functions, that would be less overhead than enabling DEBUG_THREAD. |
| 12:51.49 | coreyfarrell | if you do add a tracer make sure you call ast_log before all_events is locked, you don't want to add anything inside the lock. and honestly I have no idea how many messages you'll get from adding tracers to those functions, it could flood the logger. |
| 12:55.31 | *** join/#asterisk-dev leedm777 (~textual@2604:2d80:8404:ffae:3066:ad7a:ba9b:9586) |
| 12:55.31 | *** mode/#asterisk-dev [+o leedm777] by ChanServ |
| 13:17.21 | jkroon | coreyfarrell, it would make sense to add it before the lock since the tracer won't ever be executed inside (the threads lock on the taking of the lock). this is bizarre. i'm suspect of an external problem and the symptom merely showing here. I assume the AST_LIST_LAST() is a really, really fast operation? |
| 13:17.28 | jkroon | as in O(1) ? |
| 13:19.28 | *** join/#asterisk-dev fblackburn (~fblackbur@modemcable094.94-70-69.static.videotron.ca) |
| 13:22.46 | file | yes |
| 13:23.06 | file | the last entry is a pointer in the linked list itself, so it's directly accessible |
| 13:25.43 | jkroon | file, thanks. |
| 13:26.35 | jkroon | ok, so during normal operation it seems that 'manager show eventq' is listing anything from 7 to 300 events that's queued, so in comparison there aren't a lot more queued when lockup happens than when things operate normally, so I can't say that the queue there gets excessively large. |
| 13:37.47 | coreyfarrell | jkroon: grab_list, advance_event and append_event are all O(1) for what happens within the lock. purge_events and 'manager show eventq' are O(N) with the lock held. purge_events is run every 5 seconds. |
| 13:39.08 | jkroon | so the queue would build up for 5 seconds and then the head would get purged as they've already been transmitted to all attached manager sessions. |
| 13:39.20 | jkroon | by virtue of the ref count being zero ... |
| 13:39.49 | jkroon | i can't see that anything in there would cause any kind of problems, it's so simplistic that I honestly cannot see how anything can go wrong with that lock. |
| 13:41.44 | coreyfarrell | that's my assessment, though obviously something is going wrong if you are getting a bunch of threads waiting for the lock in append_event. |
| 13:42.56 | coreyfarrell | do you have a backtrace for all threads? |
| 13:52.04 | *** join/#asterisk-dev pchero (~pchero@x1-6-d8-d7-75-5e-99-79.cpe.webspeed.dk) |
| 13:52.24 | jkroon | i do. |
| 13:53.12 | jkroon | and i've suddenly started seeing this on three different machines over the last week, on machines where asterisk has been running nice and stable. the changes incurred: |
| 13:53.18 | jkroon | increase of dependence on astdb |
| 13:53.26 | jkroon | introcution of an addition ODBC function |
| 13:53.33 | jkroon | switch Monitor to MixMonitor |
| 13:53.47 | jkroon | all of those changes has since been backed out but the problem persists |
| 13:54.07 | jkroon | the last change before that (more than a month ago) was to utilize the AMI direct over TCP instead of via http. |
| 13:54.25 | jkroon | i'm contemplating rolling that back too now. |
| 14:00.46 | *** join/#asterisk-dev pchero (~pchero@176.23.78.252) |
| 14:08.39 | *** join/#asterisk-dev leedm777 (textual@nat/digium/x-oojxwvboyrtvfapk) |
| 14:08.39 | *** mode/#asterisk-dev [+o leedm777] by ChanServ |
| 14:09.31 | *** join/#asterisk-dev pchero (~pchero@x1-6-d8-d7-75-5e-99-79.cpe.webspeed.dk) |
| 14:17.14 | *** join/#asterisk-dev pchero (~pchero@x1-6-d8-d7-75-5e-99-79.cpe.webspeed.dk) |
| 14:24.38 | *** join/#asterisk-dev pchero (~pchero@x1-6-d8-d7-75-5e-99-79.cpe.webspeed.dk) |
| 14:50.00 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 14:50.00 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 15:04.00 | *** join/#asterisk-dev kharwell (kharwell@nat/digium/x-psyniddzqteqhhaw) |
| 15:04.00 | *** mode/#asterisk-dev [+o kharwell] by ChanServ |
| 15:37.45 | *** join/#asterisk-dev tuxd00d (~tuxd00d@ip70-190-32-9.ph.ph.cox.net) |
| 15:39.26 | *** join/#asterisk-dev tuxd00d (~tuxd00d@ip70-190-32-9.ph.ph.cox.net) |
| 15:43.24 | cresl1n | https://gerrit.asterisk.org/#/c/8398/ |
| 15:43.45 | cresl1n | Should we be putting that in non-master branches without tests? |
| 15:44.03 | cresl1n | Although the patch is super simple |
| 15:45.37 | file | I'm not torn strongly either way |
| 15:46.26 | cresl1n | Technically, it's a behavioral change and arguably a new feature |
| 15:49.55 | *** join/#asterisk-dev bford (uid283514@gateway/web/irccloud.com/x-ztosfkihkmcanljg) |
| 15:49.55 | *** mode/#asterisk-dev [+o bford] by ChanServ |
| 16:01.38 | *** join/#asterisk-dev rmudgett (rmudgett@nat/digium/x-yasihvklftjlgcrm) |
| 16:01.38 | *** mode/#asterisk-dev [+o rmudgett] by ChanServ |
| 16:23.54 | cresl1n | Alexander Traud is busy today |
| 16:24.01 | file | yes. |
| 16:27.02 | rmudgett | yes, yes he is. |
| 16:33.34 | coreyfarrell | speaking of which does anyone want to overrule me on https://gerrit.asterisk.org/8061 and https://gerrit.asterisk.org/8181 ? I don't agree with them at all but I'm willing to remove my votes if someone else wants to approve those changes. |
| 16:46.21 | *** join/#asterisk-dev Worldexe (~Worldexe@95-107-33-134.dsl.orel.ru) |
| 16:52.08 | cresl1n | coreyfarrell: I guess I'm not entirely opposed to his patch, as long as it doesn't break compatibility with linux and kin |
| 16:52.23 | cresl1n | <â just some guy |
| 18:24.05 | *** join/#asterisk-dev tuxd00d_ (~tuxd00d@ip70-190-32-9.ph.ph.cox.net) |
| 18:26.50 | *** join/#asterisk-dev tuxd00d (~tuxd00d@172.56.44.64) |
| 18:48.58 | *** join/#asterisk-dev tzafrir (~tzafrir@62-90-199-247.barak.net.il) |
| 18:48.58 | *** mode/#asterisk-dev [+o tzafrir] by ChanServ |
| 18:52.51 | *** join/#asterisk-dev tuxd00d (~tuxd00d@wsip-70-166-203-100.ph.ph.cox.net) |
| 19:01.07 | file | bit by bit gerrit improves |
| 20:23.26 | AsteriskRoss | ASTERISK-27706: If I'm seeing threads all waiting for the same lock pj_lock_acquire in pjsip_tpmgr_acquire_transport2, does that suggest the deadlock is with the transport? |
| 20:49.47 | file | somewhere in there, yes |
| 20:51.30 | AsteriskRoss | ok thanks |
| 21:21.41 | tzafrir | Qwell, ping |
| 21:48.40 | *** join/#asterisk-dev leedm777 (~textual@50-81-28-132.client.mchsi.com) |
| 21:48.40 | *** mode/#asterisk-dev [+o leedm777] by ChanServ |
| 21:58.00 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 21:58.00 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 22:18.12 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 22:18.12 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 22:22.50 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 22:22.50 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 22:29.43 | *** join/#asterisk-dev cresl1n (Adium@asterisk/libpri-and-libss7-expert/Cresl1n) |
| 22:29.43 | *** mode/#asterisk-dev [+o cresl1n] by ChanServ |
| 22:29.49 | Qwell | tzafrir: ? |
| 23:05.25 | *** join/#asterisk-dev tuxd00d (~tuxd00d@ip70-190-32-9.ph.ph.cox.net) |
| 23:38.34 | *** join/#asterisk-dev tuxd00d_ (~tuxd00d@172.58.25.246) |