Debug

Howard最近研究了一下Console Server，很好玩的说。Console Server是一种用于连接大量串口设备的设备，并且可以控制电源。这样调试kernel就方便多了。以前都是用直接连串口的方法。

今天的测试过程中发现了一个新的panic：

panic: mpt_get_request: corrupted request free list (ccb)

这个panic似乎与swap的消耗有关，初步定为为LSI SCSI卡驱动的问题。port 7上面的mpt驱动中。

Seems that my server keep tuning its clock, somewhat weird…

Jun 30 22:56:43 tarsier ntpd[412]: ntpd 4.2.0-a Thu Jun 30 11:02:35 CST 2005 (1)
Jun 30 22:56:43 tarsier ntpd[412]: no IPv6 interfaces found
Jun 30 23:05:20 tarsier ntpd[412]: kernel time sync disabled 2041
Jun 30 23:14:58 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 1 01:26:33 tarsier ntpd[412]: kernel time sync enabled 6001
Jul 1 01:43:39 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 1 09:36:14 tarsier ntpd[412]: time reset -0.152496 s
Jul 1 11:30:42 tarsier ntpd[412]: time reset +0.155343 s
Jul 1 11:30:42 tarsier ntpd[412]: kernel time sync enabled 6001
Jul 1 11:40:17 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 1 15:57:41 tarsier ntpd[412]: time reset +0.176810 s
Jul 1 15:57:41 tarsier ntpd[412]: kernel time sync enabled 6001
Jul 1 16:07:19 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 1 20:10:47 tarsier ntpd[412]: time reset -0.156077 s
Jul 1 20:20:24 tarsier ntpd[412]: time reset +0.236649 s
Jul 2 10:33:54 tarsier ntpd[412]: time reset -0.132817 s
Jul 2 16:11:24 tarsier ntpd[412]: kernel time sync enabled 6001
Jul 2 16:27:47 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 3 19:50:46 tarsier ntpd[412]: kernel time sync enabled 6001
Jul 3 20:17:51 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 4 10:12:53 tarsier ntpd[412]: time reset -0.160430 s
Jul 4 10:12:53 tarsier ntpd[412]: kernel time sync enabled 6001
Jul 4 10:22:29 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 4 20:30:43 tarsier ntpd[412]: kernel time sync enabled 6001
Jul 4 20:31:05 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 5 00:34:58 tarsier ntpd[412]: time reset +0.157389 s
Jul 5 11:00:13 tarsier ntpd[412]: time reset -0.133099 s
Jul 5 18:48:49 tarsier ntpd[412]: time reset +0.263088 s
Jul 5 18:48:49 tarsier ntpd[412]: kernel time sync enabled 6001
Jul 5 18:58:22 tarsier ntpd[412]: kernel time sync enabled 2001
Jul 5 19:57:22 tarsier ntpd[412]: time reset -0.178673 s
Jul 6 00:12:40 tarsier ntpd[412]: time reset +0.144622 s
Jul 6 09:51:10 tarsier ntpd[412]: time reset -0.132773 s
Jul 6 23:40:28 tarsier ntpd[412]: time reset +0.149341 s
Jul 7 01:53:55 tarsier ntpd[412]: time reset -0.177050 s
Jul 7 09:58:34 tarsier ntpd[412]: time reset -0.183544 s
Jul 7 12:15:14 tarsier ntpd[412]: time reset +0.158977 s
Jul 7 17:33:38 tarsier ntpd[412]: time reset +0.188230 s
Jul 7 19:31:21 tarsier ntpd[412]: time reset -0.183378 s
Jul 8 09:22:04 tarsier ntpd[412]: time reset -0.190559 s
Jul 8 10:48:50 tarsier ntpd[412]: time reset +0.144984 s
Jul 8 14:44:54 tarsier ntpd[412]: time reset +0.156142 s
Jul 8 20:13:49 tarsier ntpd[412]: time reset -0.211498 s
Jul 8 20:23:25 tarsier ntpd[412]: time reset +0.213453 s
Jul 8 23:54:54 tarsier ntpd[412]: time reset +0.171939 s
Jul 9 03:35:08 tarsier ntpd[412]: time reset -0.150036 s

Now I got (partially) the point:

• A newly fork’ed thread grabs Giant
• Subsequently, the mutex procedure will call turnstile_wait
• However, the td->td_sched->ke_runq is NULL (means that some part of the new thread is not initialized completely)
• So boom! panic.

Interestingly this does not happen in !PREEMPTION case.

Now my question are:

1. who forks?
2. is it the child? the parent?
3. why the initialization is not completed with a wrong result?

I have done several experiments/asserts to ensure that the panic is related to ULE+PREEMPTION case only.

ULE: no panic
4BSD: no panic
4BSD+PREEMPTION: no panic

My latest progress is that I found that sched_switch in ULE for the threaded case, can decide whether subsequent call would panic. Investigating.

My company has offered me some test equipment (namely, a HP 360 with ILO, which is *great* for debugging at home!), and I has started to trip over the ULE code and find for bugs.

有一天，我们发现了一个bug。

然是有人决定把它workaround掉，大家都很开心。

突然有一天，那个bug被修了。

然后workaround变成了bug……所以说坚决抵制workaround。。。

It seems that I have hit a bug, where kseq_nice_rem is being called too much. Have read the code and added some KASSERT/MPASS’es.

在-CURRENT上发表那个patch之后果然有很多热心人帮助测试。有人说在X里面接USB键盘会花，现在还在找原因……

So I finally got a big pointyhat…

This is the point:

if (!_ioctl(fd, FIODGNAME, &fgn))

So this means SUCCEEDED and the return value should be used. However, my recent commit has reverted the logic so that will fail. Seems sshd(1) don’t like this…

Fixed now.