CS444  debug logging to memory for hw3

 

Note that hw2soln and hw3’s setup has a new capability for debugging: “debuglog(s)”, where s is a string, i.e., char * pointer.  This is a trick I’ve used several times in situations where things happen very fast and ordinary output slows things down too much.  Instead of printing out as things happen, this facility stores the reports in memory until later and then outputs them.

 

For example, in tty.c’s receiver interrupt handler:

 

    sprintf(buf,"^%c", ch); /* record input char-- */

    debuglog(buf);         /* --in debug log in memory */

 

and the transmitter handler marks each interrupt with "~", with "~%c" for ordinary output, using sprintf, “debuglog(“~e”) for an echo (any echo) and debuglog(“~S”) for shutdown-transmit-ints.

 

These messages are quietly stored in memory starting at 0x300000, and ending just before 0x340000, and they are printed out at the end of the run.  By quietly, I mean they are not output at the moment, so they do not slow the processing down like kprintf’s do.  If the program crashes, you can always do

 “Tutor> md 300000” to see the log.

 

Outline of uprog.c: (provided in hw2soln)

debuglog(“user start”) 

write of "hi!\n"

write of "abcdefghi"  (9 chars, where the write returns with "defghi" still in the output queue)

debuglog(“<”)

delay loop

debuglog(“>”)

write of "AABBCC...QQ"  40 chars

read of 10 chars

write of those chars

 

Suppose the user starts typing right away, during the first delay loop, which is automated by uprog.sh in hw2soln:  The whole run will output the usual writes and echoes, and then at the end of the run, during shutdown, the kernel outputs the debuglog, like this:

 

user start~h~i~!~

~a~b~c<~d~e~f~g~h~i~S^0~e~S^1~e~S^2~e~S^3~e~S>~A^4~e~A~B~B~C~C...

  output abc by looping over enqueues (hw2 behavior, to be changed in hw3)

      < marks delay-loop start in user program

        6 chars output during start of delay loop, draining the output queue

                 ~S marks shutdown of TX ints

                   ^0~e~S marks 0 typed, echoed, shutdown TX ints

                        ^1~e~S marks 1 typed, echoed, shutdown TX ints

                              ^2~e~S marks 2 typed, echoed, shutdown TX ints

    ^3~e~S marks 3 typed, echoed, shutdown…

                                       > marks end of delay loop in user prog

                                          ~A first char of write “AA…”

                                             ^4~e marks 4 typed, echoed

                                                ~A~B~B… more chars of write

 

 

 

 

hw3: adds debuglog() reports for process switches: 

|(0-1)     for switching from process 0 to process 1

|(1z-2)   for switching from process 1, now a zombie, to process 2

|(1b-2)   for switching from process 1, now blocked, to process 2

 

After you make the scheduler properly round-robin, you should see blocking for writes of more than 6 chars, followed by other user processes running, like this, for uprogx.c (automated by hw3’s uprog.sh, which doesn’t have input):

 

|(0-1)|(1b-2)|(2b-3)~a~a~a~a~a~a~S~c|(3b-1)|(1b-2)|(2b-0)~c|(0-3)(3b-1)…

        process 1 blocks on full output Q, switch to process 2

               process 2 also sees full Q, blocks. Switch to proc. 3

                  process 3 runs loop, output drains, enq’s 6 c’s, blocks

                       int handler had unblocked 1,2,3, 3 runs now

                            Process 1 sees full Q, blocks

                                 Process 2 sees full Q, blocks

                                     process 0 chosen because 1,2,3 blocked

                                       int handler unblocks 1,2,3, 3 runs

 

It may seem strange that the one character space in the Q opened up by the interrupt handler dequeue should lead (via a call to the scheduler) to all three waiting processes unblocking, but that is the classic UNIX scheduler algorithm, with the broadcast-like wakeup.