The StackOverflow Podcast

Ads, intro

[1:00]

Spolsky: Today is the day that we did not launch, although we planned to. But then... We'll wait for another week.

Atwood: Yeah, well, the good news on that is that we did actually figure out what that problem was.    

Spolsky: Oh, oh, I want to hear, I want to hear, I want to hear.

Atwood: Eh. So, it was a third party library. Indirectly, I mean. It's the third party library, and our particular use of it. It was Log4Net.

Spolsky: Oh!

Atwood: We were logging in such a way that the log.... during the log call was triggering another log call. Which is normally okay, but with the load that we have, eventually they would happen so close together that there's also a lock. So, there's two locks going on there. There's a lock of like disposing of the database stuff that's going on. Then there's lock of like actually writing to a file...

Spolsky: Hm!

Atwood: And... Huh... They happen in the opposite order, so it's like a classic deadlock, right. So, you release the lock on the database, then you release the lock on the file. And then the other call was doing in the other order. And they were happenning so fast that... it was deadlocking eventually. And it was one of those things that would happen.. like... it was very [intermittent [??]], right.

Spolsky: Right.

Atwood: So we had to dust-off Win Debug.

Spolsky: How on Earth do you find things like that?

Atwood: Well. You bust that Win Debug. One nice feature in Windows 2008, and I think this is in Vista as well. In Task Manager, you can right-click a task and take a dump of it.

Spolsky: Yeah!

Atwood: Like right there.

Spolsky: Aha.

Atwood: So we took a dump of the W3Service process, and...

Spolsky: [Then [??]] take a dump.

Atwood: Yeah, I know, any time you do this it's like.. It's like the teritorry for jokes. It's just...

Spolsky: [giggles]

Atwood: [laughs]. And then we loaded up a... Win... Debug.

Spolsky: Windbg! Yeah

Atwood: ...and then some .Net managed extensions you can, sort of load. You need like a chi-chi to figure out what the commands are. And then you load the dump, and you load the manage tools. And then you can sort of just investigate all of the threads. You can take the "Show me all the manage threads." And then say "Show me what's the call stack was for that thread." And what we saw was like tons and tons of threads that were all going "Hey, I would like to log something..." And it was like "Hmmmm... [laughs]... Interesting!" Right, you have like 80 threads that all try to write something to the log. So... Right then we kind of knew where the problem was.

And then somebody on Twitter actually volunteered to help us diagnose the dump. So I put it up on our server, and he a.... he nailed... he had a great description of it, like line by line, blow by blow of exactly what was happening. I mean, I'm... I'm competent enough to sort of figure out roughly what was going on, but he really knew this stuff and really helped us out, and I do appreciate that.

[3:33]

Spolsky: That's really awesome.

Atwood: So yeah. We.. we ripped out all the logging. I was never a huge fan of logging. I mean I guess there's a couple of philosophies on this. Like which is your philosophy with logging, like as you sit down to write a function, like would you add logging to it? I mean what's your ..what's your philosophy ? I'm curious. [[??]]

Spolsky: I'd never .. no ... I never do ..I nev.. But you know I don't... I don't think I've ever worked on code that is sort of [operational] in the same way.

Atwood: ah hm.

Spolsky: Eh.. because we definitly eh.. put a lot more ... oh [you know] I did, at Yuno we used to have all kinds of logging.
The trouble is that my philosophy has always been that you .. you.. you have a tendency to wanna log everything. But then you just get logs that are, you know, a hundred megabyte per user and you get thirty of them a minute and it can't possibly be analyzed or stored in any reasonable way. So the next thing you have to do is to start [??coloring??] your logs or just have different levels of debugging, where it's like in high debug mode everything is logged and in low debug mode nothing is logged. And... it's kind of hard to figure out what you really want in a log. You you know you know .. a lot of logs, like I think of the logging that we did in Yuno, where people would call with a complaint and you try to figure out where this programm is crashing. And obviously a log of the crash, that's easy. Ehm, but then there's some line above the crash which hopefully gives you a lot of information about where it happend. And there's some line you don't see that should have been after that, after the crash, but it never got there 'cause it crashed sometime before there. And essentially what you're doing as you're adding logging, is you're doing binary search, right, where you're [sticking in] like "well gosh, I got to here and then got to there. But there's an awful lot of code between point A and point B. So let's make an A you know half-way from A to B, log point of some sort". Then you put that in and then you eliminate 50 percent of the possible places to look for your crash.
[05:16]


Atwood: edit me!

Spolsky: edit me!