[00:53:06] --- lars.malinowsky has become available [01:44:50] --- Russ has left: Disconnected [03:23:47] magic sysrq has a lock dump mode, but only for "real" locks. So it will show you holders of the AFS GLOCK, but none of our internal locks. [03:24:31] You only get the really decent Linux lock debugging if you compile the kernel with it enabled. But then it changes all of the locking primitives to GPL-only symbols. So, we lose. [03:52:12] --- lars.malinowsky has left [03:57:39] --- reuteras has left [04:04:41] --- reuteras has become available [04:37:45] --- aamaadmi has become available [04:40:42] --- reuteras has left [04:50:43] they probably compile their kernel [04:51:08] and in this case, it would show the holder of a real lock: call->lock [04:52:15] alt-sysrq-d, if the necessary goo is built into the kernel [04:52:21] there are only 2 tasks blocked. one, CheckServerDaemon, is blocked in either a conn_call or conn_data lock to a vlserver. the other, inlinebulk, is presumably not talking to a vlserver given where it is, so it's not the same conn. and given the offset, i assume it's a call->lock [04:52:46] er, only 2 tasks blocked outside a kernel lookup path [04:52:59] (and those are presumably waiting on the inlinebulk) [05:17:30] --- abo has left [05:32:19] --- abo has become available [05:34:42] --- meffie has become available [05:48:32] --- lars.malinowsky has become available [05:59:15] --- jaltman/FrogsLeap has left: Disconnected [06:02:49] --- ksumner has become available [06:11:14] --- reuteras has become available [07:35:40] --- deason has become available [07:55:11] --- reuteras has left [08:02:45] --- Simon Wilkinson has left [08:03:47] --- aamaadmi has left [08:04:30] --- snktagarwal has become available [08:05:24] --- Simon Wilkinson has become available [08:08:47] --- snktagarwal has left [08:09:25] --- snktagarwal has become available [09:33:44] --- lars.malinowsky has left [09:37:59] --- lars.malinowsky has become available [09:41:15] --- lars.malinowsky has left [09:45:22] how are rx replies processed? [09:45:39] (i really should ask more specific questions i guess) [09:49:12] do you mean ACKs? or, like, the data supplied in response to an rpc? [09:50:04] i mean, how a something waiting on a reply gets notified one arrived [09:51:20] inside rx? their cv is signalled. or you mean as an api caller? [09:52:05] okay, signalled cv, why isn't that happening always for me? [09:52:39] what's the afsd process that's always waiting for network input doing? [09:54:24] --- snktagarwal has left [09:54:55] the cv facility is the kernel's (or pthreads'). so, i can't tell you. it's.... blocking waiting for a packet to show up, so it can read and process it [09:55:11] those are 2 answers to 2 questions. [09:55:32] note that on osx 10.6 in 1.6.0pre4 we don't block and wait for packets. [09:56:00] the code is otherwise the same: when a packet comes in for us, it is processed and anyone waiting is notified [09:56:37] in any case, you have basically 2 choices: your cv wrapper is broken, or your kernel is broken [09:56:48] it works everywhere else. [09:58:24] it mostly works for me, except when it doesn't :-) [09:58:42] get it stuck on a unresponsive cell and it never dies [09:59:02] printfs on things which are about to wait and on things which either signal or broadcast a wakeup? [09:59:30] ah, that's different. you want... (ahng on) [10:00:38] you want to see if rxi_ResetCall is ever being called on your cv_rq. [10:00:58] rxdebug should tell you if the call has a reader wait flag set [10:07:16] path that would time out your calls: rxi_CheckCall -> rxi_FreeCall -> rxi_ResetCall. the keepalive events are responsible for ensuring this is called. for server connections it's dne differently, but i assume this is a client connect (e.g. client calling a fileserver for data, and you are the caller, not the callee) [10:13:23] keepalive events, where are those? [10:13:58] --- rra has become available [10:14:02] uh. ask a better question [10:14:25] what causes them? [10:14:56] a call to rxi_ScheduleKeepAliveEvent? or do you mean... [10:15:30] rx_NewCall calls e.g. rxi_KeepAliveOn(call); [10:19:30] they're run by the rx event thread, if you mean from where the events themselves are run [10:22:19] ScheduleKeepAliveEvent et al is what turns them on, to be run later by.... afs_rxevent_daemon -> rxevent_RaiseEvents (or maybe a couple of other entry points, I forget) [10:23:15] The thing to watch out for with stuff that's called from the rx_Event thread is that sometimes it isn't, which plays havoc with some of the rx library's locking rules. But that shouldn't apply in this case. [10:41:35] how often would rxevent_RaiseEvents happen? [10:49:10] It's scheduled, according to when the last event was handled. [10:49:43] Take a look at the code in src/rx/rx_event.c [10:54:36] it looks like it's called every 500ms in afs_rxevent_daemon, though [10:55:24] Ah. I was just thinking of the userspace case. [10:55:59] except if you are RXK_TIMEDSLEEP_ENV e.g. macos; said code should be made available elsewhere, and should probably be willing to sleep longer. [10:56:11] We really shouldn't be waking the kernel every 500ms, when we know when the next event will occur. That will make power consumption watchers unhappy. [10:57:05] well, that was the point of RXK_TIMEDSLEEP_ENV [10:59:14] On modern kernels, is there any reason that we can't just do what we do in userspace, and schedule the next wakeup based on when the next event is scheduled for? [10:59:53] so, basically, what RXK_TIMEDSLEEP_ENV does? [11:00:06] yeah, my response to that is "see derrick" :) [11:00:23] I thought that still woke more frequently than absolutely required? [11:00:50] it uses the time from the RaiseEvents arg [11:01:03] it does, but that can be changed trivially. i made it conservative when i changed it. [11:01:23] well, it does, but it has that pesky MAX(500, x) [11:01:45] doesn't that just make it refuse to wake up _more_ often than 500ms? [11:02:20] Yeah, actually that's what I was just thinking. I'd had it explained to me that there was a top bound on how long we sleep for, but I can't see that top bound anywhere. [11:02:46] ah, true. [11:03:01] so i was smart, and just don't remember it. and then MAX, MIN, whatever. [11:04:34] Did jhutz not do work on making AFS play nicer in low power environments on Linux? I wonder if he ever tried TIMEDSLEEP_ENV there... [11:04:45] it didn't exist then, so no [11:05:47] Does it rely on particular operating system functionality, or were you just being cautious? [11:06:12] afs_osi_TimedSleep didn't exist everywhere, and when i wrote it everywhere, i didn't test it everywhere [11:07:02] the idea was that we'd test it elsewhere and then make it available. "oops" [11:08:22] hmm, my timeval might be wrong ish [11:08:56] i recommend against that [11:09:40] it's composed of 'long's [11:10:00] (or in -current, something always 64-bit for the seconds) [11:10:36] I'm more in favour of the "turn it on and see who screams" approach :) [11:11:11] you also are in favor of spelling favor wrong, so i'm not sure we should trust your approach very far ;) [11:12:49] hmm, i'm little endian, and the offsetof tv_usec in osi_timeval_t is right anyway [11:13:30] oh. but struct clock. [11:13:41] yeah, that's not going to work [11:14:27] something is memcpy'ing struct clocks to/from struct timevals or something, I take it? [11:14:34] i think so [11:15:17] why isn't struct clock just a osi_timeval_t? [11:16:06] hmm. maybe it's more right than i thought [11:16:29] oh, that's in pthread [11:16:42] you're looking for KERNEL; yeah, the clock code is a bit of an ifdef maze iirc [11:18:19] I think your relevant clock_GetTime is #define clock_GetTime(cv) osi_GetTime((osi_timeval_t *)(cv)) [11:18:28] and osi_GetTime is microtime(); I assume that won't work [11:18:55] yeah, i don't think it will, tv_usec is at offset 8 [11:20:36] I'd guess if you add nbsd to the set of defines that does the explicit tv->struct clock conversion above, you'd be better off [11:27:49] hmm, is this code in afsd or the kernel libafs? [11:28:38] nothing interesting in afsd. [11:29:13] afsd does like 2 things: fork, and make syscalls. i overstate simplicity, but in generally "these are not the droids you are looking for" [11:29:47] got it [11:29:52] libafs, yeah [11:29:57] --- deason has left [11:29:59] --- deason has become available [11:30:34] At some point we should also pull the cache scan out of libafs. System startup with large caches is getting to be really really painful [11:30:53] s/libafs/afsd. Out of afsd, and put it into the kernel module. [11:32:05] basically, the change you want to make is about line 95 in src/rx/rx_clock.h [11:32:47] i've done that, i've got a few more things to look at though [11:33:02] anything else you need help with? [11:33:51] not at the moment [11:34:19] i know i need to get rxevent_RaiseEvents to happen [11:38:01] --- meffie has left [11:38:10] --- meffie has become available [11:54:59] i see, tsleep and cv_timedwait on netbsd, when called with a 0 timeout value sleep forever [11:57:02] that's not surprising [11:57:35] well, the existing code found it surprising [14:03:03] are file descriptor limits relevant to the client? [14:05:13] Potentially, depending on exactly how (and where) your kernel enforces them [14:09:50] 21:09:20.272631 IP 172.27.42.121.7001 > 18.9.60.97.7000: rx version (29) [14:10:00] is that supposed to get a reply? [14:11:26] Only if it's going from client to server [14:12:28] that could be a version response packet, which we send periodically to keep udp mappings alive for NATs and such [14:12:40] in which case, there's not supposed to be any reply [14:13:12] oh [14:13:16] iirc if the CLIENT_INITIATED flag is set you're supposed to get a reply, otherwise no [14:13:37] Yeah. If CLIENT_INITIATED is clear, the server will just drop the packet. [14:13:48] which you don't see at that level of detail in what I assume is tcpdump.... I'm not sure if it displays it at higher verbosity or something [14:14:31] well, anyway. even after getting the rxevent stuff going at a decent pace, it still like stalling [14:15:01] so you see rxevent_RaiseEvents firing... do you see rxi_CheckCall getting called? [14:15:36] occasionally [14:16:02] like just now [14:16:04] It's also worth checking that the kernel isn't throwing away UDP packets under you. [14:16:17] you should see rxi_CheckCall eventually, and eventually you should see it call rxi_CallError if you haven't received any packets in awhile [14:16:50] Do you stall completely, and the machine hang, or do you eventually hit a timeout? [14:17:03] but even if you're not getting udp packets, the call should timeout; jakllsch, you're seeing something stuck waiting for an rx call to return, aren't you? [14:17:14] at least, that's what I thought it was before [14:17:31] well, at the moment, rxdebug says i'm good [14:18:22] i think, maybe [14:19:38] at the moment, i tab completed in /afs/, it still hasn't gotten anywhere after maybe an hour [14:20:06] That's a bad test, because even if every call times out, you can still end up waiting a long time [14:20:20] it was an accident :-) [14:20:51] Hmmm. Are you running afsd with fakestat enabled, though? [14:21:03] (fakestat saves you from the pain of /afs/ ) [14:21:22] probably not [14:22:17] Are you still seeing RX traffic as a result of your tab expansion, or is all quiet on the network front? [14:25:02] quiet except for those version packets [14:27:05] And where are they going? [14:29:15] (one host, or many, would be good to get any idea of whether its actually progressing through the tab expansion) [14:30:28] many, (anyway, i rebooted) [14:33:26] --- mdionne has become available [14:36:50] okay, with fakestat it's working more tolerably [14:38:51] or, maybe not so much [14:39:07] fakestat wont' [14:39:15] won't hit the network for anything under /afs [14:39:16] i doubt fakestat fixes it. you seem to have a real issue [14:40:08] The thing to do is to grab a packet trace of the first RX connection your cache manager makes, and see whether packets are getting ACK'd or not. [14:45:17] --- pod has left [15:21:43] --- deason has left [16:24:24] --- meffie has left [16:34:37] --- jaltman/FrogsLeap has become available [16:39:59] --- deason has become available [16:46:29] --- jaltman/FrogsLeap has left: Replaced by new connection [16:46:30] --- jaltman/FrogsLeap has become available [16:48:25] hmm, they do appear to be getting acked, but apparently the client isn't (always) seeing it [17:01:48] --- rra has left: Disconnected [17:31:23] --- Russ has become available [17:33:00] --- jaltman/FrogsLeap has left: Disconnected [17:33:08] --- jaltman/FrogsLeap has become available [19:29:17] --- mdionne has left [20:32:58] --- jaltman/FrogsLeap has left: Replaced by new connection [20:32:59] --- jaltman/FrogsLeap has become available [20:36:02] --- cudave has left: Disconnected [20:37:47] --- jaltman/FrogsLeap has left: Replaced by new connection [20:37:48] --- jaltman/FrogsLeap has become available [20:42:00] --- cudave has become available [20:50:56] --- jaltman/FrogsLeap has left: Disconnected [21:26:38] --- jaltman/FrogsLeap has become available [21:32:36] --- deason has left [22:18:59] --- reuteras has become available