New donator - thanks, Michael Roach!
[ikiwiki.git] / docs / howtos / HowToDebugVKernels / index.mdwn
index 8c58c4a..971d5b5 100644 (file)
@@ -21,7 +21,7 @@ Here comes the fun. I misread the [ktrace(1)](http://leaf.dragonflybsd.org/cgi/w
 
 And the system hang.
 
-(My intention was to track the system calls of t_aio, but what I typed would actually disable all traces from all process to the t_aio file.)
+My intention was to track the system calls of t_aio, but what I typed would actually disable all traces from all processes to ktrace.out, the default tracing file. Out of pure luck, a bug has been discovered.
 
 # Setup a vkernel
 To setup a vkernel, please consult [this man page](http://leaf.dragonflybsd.org/cgi/web-man?command=vkernel&section=ANY).
@@ -76,7 +76,7 @@ Let's get a trace of what went wrong:
     go_user(5709dd38,0,0,7b,0) at 0x82151ac
     db> 
 
-Here sys_ktrace, allproc_scan, etc represent function names. Functions are listed in the _reverse_ order they were called. Thus, in this particular example, the last function which was called is ktrdestroy(). The hex values in parentheses are the first five items on the stack. The last hex value is the [instruction address](http://en.wikipedia.org/wiki/Program_counter). Since ddb doesn't really know how many arguments a function takes, it always prints five.
+Here sys_ktrace, allproc_scan, etc represent function names. Functions are listed in the _reverse_ order they were called. Thus, in this particular example, the last function which was called is ktrdestroy(). The hex values in parentheses are the first five items on the stack. Since ddb doesn't really know how many arguments a function takes, it always prints five. The last hex value is the [instruction address](http://en.wikipedia.org/wiki/Program_counter).
 
 # Gdb
 
@@ -135,6 +135,7 @@ At this point we can examine the data of various variables. Keep in mind that ba
 
 
 Let's try this time to break into the kernel _before_ it crashes. sys_ktrace() seems like a good candidate.
+We stop the old vkernel and fire off a new one. Once we are logged in, we attach to it as before:
 
     # gdb kernel 25532
     GNU gdb 6.7.1
@@ -148,7 +149,7 @@ Next we type 'c' in the gdb prompt to resume vkernel execution:
     (gdb) c
     Continuing.
 
-Now we go to our vkernel and type the offending command:
+We switch now to our vkernel and type in the offending command:
 
     # ktrace -c 
 
@@ -158,12 +159,13 @@ Gdb stops the execution of vkernel and a message pops up in gdb buffer:
     83          __asm ("movl %%fs:globaldata,%0" : "=r" (gd) : "m"(__mycpu__dummy));
     (gdb) 
 
-We navigate through source code with the 'step' and 'next' gdb commands. They are identical, except that 'step' follows function calls. When we meet this call:
+At this point, kernel hasn't paniced yet, because we are inside sys_ktrace().
+We navigate through source code with the 'step' and 'next' gdb commands.
+They are identical, except that 'step' follows function calls. When we meet this call:
 
     276                     allproc_scan(ktrace_clear_callback, &info);
 
-we 'step' inside it. alloproc_scan() iterates through the process list and applies the ktrace_clear_callback() to each one of them.
-Later we see this:
+we 'step' inside it. The alloproc_scan() function, iterates through the process list and calls ktrace_clear_callback() for each one of them. Later we see this:
 
     347                     if (p->p_tracenode->kn_vp == info->tracenode->kn_vp) {
 
@@ -172,15 +174,15 @@ Here p is a pointer to the current process:
     (gdb) print p
     $1 = (struct proc *) 0x57098c00
 
-Let's see if this process is traced:
+Let's see if this process is traced (if it is, the p->p_tracenode->kn_vp shall point to a vnode where all logs are directed):
 
     (gdb) print p->p_tracenode
     $2 = (struct ktrace_node *) 0x0
     (gdb) 
 
-Oops. There is no trace to a vnode for this process. The code will try to access p->p_tracenode and is bound to crash. This is the zero virtual address we saw before.
+Oops. There is no trace to any vnode for this process. The code will try to access p->p_tracenode->kn_vp and is bound to crash. This is the _zero virtual address_ we saw before. It seems that the kernel tries to disable tracing of all processes indiscriminately, even of those that aren't traced. Now that we know the root of problem we write a [patch](http://gitweb.dragonflybsd.org/dragonfly.git/commit/a4a639859f6bc14f9f55142b4bd2289b2a56d7f2) and poke someone to review/commit it.
 
-# Possible errors
+# Possible places of confusion
 
     (gdb) bt
     #0  0x282d4c10 in sigsuspend () from /usr/lib/libc.so.6
@@ -192,5 +194,37 @@ Oops. There is no trace to a vnode for this process. The code will try to access
     #6  0x00000000 in ?? ()
     (gdb) 
 
-Why does it differ from the ddb's trace ?
-Well, when the vkernel is sitting at a db> prompt all vkernel threads representing virtual cpu's except the one handling the db> prompt itself will be suspended in stopsig(). The backtrace only sees one of the N threads.
+When the vkernel is sitting at a db> prompt all vkernel threads representing virtual cpu's except the one handling the db> prompt itself 
+will be suspended in stopsig(). The backtrace only sees one of the N threads.
+
+# Additional notes
+## Accessing Vkernels memory
+For those using HEAD, some changes in libkvm have been introduced so vkernel's memory can be accessed directly now on /proc/$pid/mem.  
+
+Among other things, you can have a look at vkernel's process list using ps:
+
+
+    # ps axl -M /proc/829/mem -N /var/vkernel/boot/kernel
+    UID   PID  PPID CPU PRI  NI   VSZ  RSS WCHAN  STAT  TT       TIME COMMAND
+     0     0    -1   1 152   0     0 3068 nowork DL    ??    0:00.00  (swapper)
+     0     1     0   0 152   0   760 3068 wait   IL    ??    0:00.00  (init)
+    77   212     1   0 152   0   788 3068 poll   S     ??    0:00.00  (dhclient)
+     0   323     1   0 152   0  1288 3068 select S     ??    0:00.00  (syslogd)
+     0   627     1 115 222   0  3332 3068 select I     ??    0:00.00  (sshd)
+     0   641     1   0 152   0  3772 3068 select S     ??    0:00.00  (sendmail)
+    25   645     1  22 165   0  3668 3068 pause  I     ??    0:00.00  (sendmail)
+     0     0     0   0   0 -52     0    0 -      ?    con-   0:00.00  ()
+     0     0     0   0   0 -52     0    0 -      ?    con-   0:00.00  ()
+     0     0     0   0   0 -52     0    0 -      ?    con-   0:00.00  ()
+     0   188     1   2 153   0   788 3068 poll   I     v0-   0:00.00  (dhclient) 
+
+
+## Gdb + vkernel issues
+gdb and vkernel (SMP or not) don't play well together anymore.  It is possible to get into
+a state where the vkernel is in state "stop" and the vkernel is in "wait", and nothing moves on.
+The only help is to kill gdb, which either makes the vkernel run again, or kills it as well.
+
+See also [this bug report](http://bugs.dragonflybsd.org/issue1301).
+
+Experience has shown that running vkernel with -n1, that is telling it to emulate only 1 CPU, alleviates the issue.
+