CSC 343 - Operating Systems, Spring 2024, TuTh 12-1:20 or 1:30-2:50. Old Main 159.
Interpreting State Machine Log Files.
We will go over this before Assignment 2. My parts are in red.
CSC343 How to Interpret State Machine Log Files when you
have bugs.
I am using spring 2024's Assignment 1 to demo.
$ make clean test
... (LINES DELETED)
COMPLETED (OK) SIMULATING (TESTING) prisonerd2024
$ ls -l *.stm *.log
lrwxrwxrwx. 1 parson domain users 58
Feb 6 12:24 prisonerd2024.log ->
/home/kutztown.edu/parson/tmp/parson_STM_prisonerd2024.log
-rw-r--r--. 1 parson domain users 10375 Jan 31 16:58
prisonerd2024.stm
$ ls -l *.stm *.log
lrwxrwxrwx. 1 parson domain users 58
Feb 6 12:24 prisonerd2024.log ->
/home/kutztown.edu/parson/tmp/parson_STM_prisonerd2024.log
-rw-r--r--. 1 parson domain users 10375 Jan 31 16:58
prisonerd2024.stm
The LOG file is a symbolic link to a
text file stored in ~parson/tmp/.
I put LOG files there to save student file system space.
$ head -20 prisonerd2024.log
# Show me the first 20 lines of this LOG file.
000000000000,LOG,processor 0,init,init
000000000000,LOG,processor 0,init,APPROACH
000000000000,LOG,processor 0,init,ARRIVE
000000000000,LOG,processor 0,init,DEPART
000000000000,LOG,processor 0,makingProcesses,APPROACH
000000000000,LOG,thread 0 process 0,init,init
000000000000,LOG,processor 0,makingProcesses,fork
000000000000,LOG,processor 0,makingProcesses,ARRIVE
000000000001,LOG,thread 0 process 0,init,APPROACH
000000000001,LOG,thread 0 process 0,init,ARRIVE
000000000001,LOG,thread 0 process 0,init,DEPART
000000000001,LOG,thread 0 process 0,initThread,APPROACH
000000000001,MSG,thread 0 process 0,Example DEBUG message, pid
= 0 tid = 0
000000000001,LOG,thread 0 process 0,initThread,cpu
000000000001,LOG,thread 0 process 0,initThread,ARRIVE
000000000001,LOG,processor 0,makingProcesses,REPEAT
000000000001,LOG,thread 0 process 1,init,init
000000000001,LOG,processor 0,makingProcesses,fork
000000000001,LOG,thread 0 process 0,initThread,DEPART
000000000001,LOG,thread 0 process 0,sendMyAction,APPROACH
$ tail -20 prisonerd2024.log
# Show me the last 20 lines of this LOG file.
000000000310,LOG,thread 0 process 1,awaitOtherAction,DEPART
000000000310,LOG,thread 0 process 1,timeInJail,APPROACH
000000000310,LOG,thread 0 process 1,timeInJail,cpu
000000000310,LOG,thread 0 process 1,timeInJail,ARRIVE
000000000310,LOG,thread 1 process 1,awaitOtherAction,ARRIVE
000000000310,LOG,thread 1 process 1,awaitOtherAction,DEPART
000000000310,LOG,thread 1 process 1,timeInJail,APPROACH
000000000310,LOG,thread 1 process 1,timeInJail,cpu
000000000310,LOG,thread 1 process 1,timeInJail,ARRIVE
000000000310,LOG,thread 0 process 1,timeInJail,DEPART
000000000310,LOG,thread 0 process 1,terminated,APPROACH
000000000310,LOG,thread 0 process 1,terminated,ARRIVE
000000000310,LOG,thread 0 process 1,terminated,DEPART
000000000310,LOG,thread 0 process 1,<defunct>,?
000000000313,LOG,thread 1 process 1,timeInJail,DEPART
000000000313,LOG,thread 1 process 1,terminated,APPROACH
000000000313,LOG,thread 1 process 1,terminated,ARRIVE
000000000313,LOG,thread 1 process 1,terminated,DEPART
000000000313,LOG,thread 1 process 1,<defunct>,?
000000000313,MSG,scheduler,Scheduler exiting at time 313
within time limit 500, simulation has finished.
Running "less" lets you walk through
a text file a line or screen at a time.
Hit the SPACE bar for the next screen or ENTER for one
line.
You can use up-arrow to go up in the file.
You can search forward with:
/SEARCHSTRING<Enter>
or backwards with:
?SEARCHSTRING<Enter>
$ less prisonerd2024.log
000000000000,LOG,processor 0,init,init
000000000000,LOG,processor 0,init,APPROACH
000000000000,LOG,processor 0,init,ARRIVE
000000000000,LOG,processor 0,init,DEPART
000000000000,LOG,processor 0,makingProcesses,APPROACH
000000000000,LOG,thread 0 process 0,init,init
000000000000,LOG,processor 0,makingProcesses,fork
000000000000,LOG,processor 0,makingProcesses,ARRIVE
000000000001,LOG,thread 0 process 0,init,APPROACH
000000000001,LOG,thread 0 process 0,init,ARRIVE
000000000001,LOG,thread 0 process 0,init,DEPART
000000000001,LOG,thread 0 process 0,initThread,APPROACH
000000000001,MSG,thread 0 process 0,Example DEBUG message, pid
= 0 tid = 0
000000000001,LOG,thread 0 process 0,initThread,cpu
000000000001,LOG,thread 0 process 0,initThread,ARRIVE
000000000001,LOG,processor 0,makingProcesses,REPEAT
000000000001,LOG,thread 0 process 1,init,init
000000000001,LOG,processor 0,makingProcesses,fork
000000000001,LOG,thread 0 process 0,initThread,DEPART
000000000001,LOG,thread 0 process 0,sendMyAction,APPROACH
000000000001,LOG,thread 1 process 0,init,init
000000000001,LOG,thread 0 process 0,sendMyAction,spawn
000000000002,LOG,thread 0 process 1,init,APPROACH
000000000002,LOG,thread 0 process 1,init,ARRIVE
000000000002,LOG,thread 0 process 1,init,DEPART
000000000002,LOG,thread 0 process 1,initThread,APPROACH
000000000002,MSG,thread 0 process 1,Example DEBUG message, pid
= 1 tid = 0
000000000002,LOG,thread 0 process 1,initThread,cpu
000000000002,LOG,thread 0 process 1,initThread,ARRIVE
000000000002,LOG,processor 0,makingProcesses,REPEAT
000000000002,LOG,thread 0 process 2,init,init
000000000002,LOG,processor 0,makingProcesses,fork
You can PIPE the output of head or
tail to less:
$ head -200 prisonerd2024.log |less
$ tail -200 prisonerd2024.log |less
You can use grep (get regular
expression) to search for a literal string:
$ grep MSG prisonerd2024.log |
less
000000000001,MSG,thread 0 process 0,Example DEBUG
message, pid = 0 tid = 0
000000000002,MSG,thread 0 process 1,Example DEBUG
message, pid = 1 tid = 0
000000000002,MSG,thread 1 process 0,Example DEBUG
message, pid = 0 tid = 1
000000000002,MSG,thread 0 process 0,WARNING,
signalEvent discards event type receiveOtherAction
because model is waiting in
queue: waiting on simulation scheduler (simulation
sleep) for model:
Thread pid 0, tid 0, state
sendMyAction, waitingon cpu, __sleepResult__ None,
__isdead__False
000000000003,MSG,thread 0 process 2,Example DEBUG
message, pid = 2 tid = 0
000000000003,MSG,thread 1 process 1,Example DEBUG
message, pid = 1 tid = 1
000000000003,MSG,thread 0 process 1,WARNING,
signalEvent discards event type receiveOtherAction
because model is waiting in
queue: waiting on simulation scheduler (simulation
sleep) for model:
Thread pid 1, tid 0, state
sendMyAction, waitingon cpu, __sleepResult__ None,
__isdead__False
000000000004,MSG,thread 0 process 3,Example DEBUG
message, pid = 3 tid = 0
000000000004,MSG,thread 1 process 2,Example DEBUG
message, pid = 2 tid = 1
000000000004,MSG,thread 0 process 2,WARNING,
signalEvent discards event type receiveOtherAction
because model is waiting
in queue: waiting on simulation scheduler
(simulation sleep) for model:
Thread pid 2, tid 0, state
sendMyAction, waitingon cpu, __sleepResult__ None,
__isdead__False
Running grep with -v discards
matching line:
$ grep MSG prisonerd2024.log | grep -v WARNING
000000000001,MSG,thread 0 process 0,Example DEBUG message, pid
= 0 tid = 0
000000000002,MSG,thread 0 process 1,Example DEBUG message, pid
= 1 tid = 0
000000000002,MSG,thread 1 process 0,Example DEBUG message, pid
= 0 tid = 1
000000000003,MSG,thread 0 process 2,Example DEBUG message, pid
= 2 tid = 0
000000000003,MSG,thread 1 process 1,Example DEBUG message, pid
= 1 tid = 1
000000000004,MSG,thread 0 process 3,Example DEBUG message, pid
= 3 tid = 0
000000000004,MSG,thread 1 process 2,Example DEBUG message, pid
= 2 tid = 1
000000000005,MSG,thread 0 process 4,Example DEBUG message, pid
= 4 tid = 0
000000000005,MSG,thread 1 process 3,Example DEBUG message, pid
= 3 tid = 1
000000000006,MSG,thread 0 process 5,Example DEBUG message, pid
= 5 tid = 0
000000000006,MSG,thread 1 process 4,Example DEBUG message, pid
= 4 tid = 1
000000000007,MSG,thread 0 process 6,Example DEBUG message, pid
= 6 tid = 0
000000000007,MSG,thread 1 process 5,Example DEBUG message, pid
= 5 tid = 1
000000000008,MSG,thread 0 process 7,Example DEBUG message, pid
= 7 tid = 0
000000000008,MSG,thread 1 process 6,Example DEBUG message, pid
= 6 tid = 1
000000000009,MSG,thread 0 process 8,Example DEBUG message, pid
= 8 tid = 0
000000000009,MSG,thread 1 process 7,Example DEBUG message, pid
= 7 tid = 1
000000000010,MSG,thread 0 process 9,Example DEBUG message, pid
= 9 tid = 0
000000000010,MSG,thread 1 process 8,Example DEBUG message, pid
= 8 tid = 1
000000000011,MSG,thread 1 process 9,Example DEBUG message, pid
= 9 tid = 1
000000000313,MSG,scheduler,Scheduler exiting at time 313
within time limit 500, simulation has finished.
The above WARNINGS do not matter in this assignment.
The following macro uses "trigger" when this event has
already passed.
macro SendRecvSync @
pcb.incomingMessage[othertid] = SendRecvAction ;
signalEvent(pcb.partners[othertid], "receiveOtherAction",
SendRecvAction);
waitForEvent('receiveOtherAction', False)
if not pcb.incomingMessage[tid]
else trigger(0, 'receiveOtherAction',
pcb.incomingMessage[tid])
000000000019,LOG,thread 0 process 5,timeInJail,DEPART
000000000019,LOG,thread 0 process 5,sendMyAction,APPROACH
000000000019,LOG,thread 0 process 5,sendMyAction,cpu
000000000019,LOG,thread 0 process 5,sendMyAction,ARRIVE
... OTHER LINES IN LOG FILE
000000000019,MSG,thread 0 process 5,WARNING, signalEvent
discards event type receiveOtherAction
because model is waiting in queue: waiting
on simulation scheduler (simulation sleep) for model:
Thread pid 5, tid 0, state sendMyAction,
waitingon cpu, __sleepResult__ None, __isdead__False
000000000019,LOG,thread 0 process 5,sendMyAction,DEPART
000000000019,LOG,thread 0 process 5,awaitOtherAction,APPROACH
000000000019,LOG,thread 0 process
5,awaitOtherAction,receiveOtherAction
000000000019,LOG,thread 0 process 5,awaitOtherAction,ARRIVE
... OTHER LINES IN LOG FILE
000000000019,LOG,thread 0 process 5,awaitOtherAction,ARRIVE
000000000019,LOG,thread 0 process 5,awaitOtherAction,DEPART
000000000019,LOG,thread 0 process 5,timeInJail,APPROACH
000000000019,LOG,thread 0 process 5,timeInJail,cpu
000000000019,LOG,thread 0 process 5,timeInJail,ARRIVE
... OTHER LINES IN LOG FILE
000000000020,LOG,thread 0 process 5,timeInJail,DEPART
000000000020,LOG,thread 0 process 5,sendMyAction,APPROACH
000000000020,LOG,thread 0 process 5,sendMyAction,cpu
000000000020,LOG,thread 0 process 5,sendMyAction,ARRIVE
Running make clean test on
Assignment 1:
/bin/bash -c
"PYTHONPATH=/home/kutztown.edu/parson/OpSys:.:..:/usr/local/lib/python3.7
/usr/local/bin/python3.7 crunchlog.py prisonerd2024.log"
DIFFing prisonerd2024_crunch.py prisonerd2024_crunch.ref
OK: SUM_timeInJail_thread_0_process_0 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_0 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_1 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_1 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_2 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_2 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_3 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_3 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_4 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_4 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_5 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_5 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_6 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_6 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_7 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_7 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_8 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_8 at 20.0% tolerance.
OK: SUM_timeInJail_thread_0_process_9 at 20.0% tolerance.
OK: SUM_timeInJail_thread_1_process_9 at 20.0% tolerance.
To see these in the output and
reference (of expected output) files:
grep SUM_timeInJail_thread_0_process_0 prisonerd2024_crunch.py
prisonerd2024_crunch.ref
prisonerd2024_crunch.py:SUM_timeInJail_thread_0_process_0=200
prisonerd2024_crunch.ref:SUM_timeInJail_thread_0_process_0=200
"egrep" (extended grep) allows
searching for alternative strings
like "ARRIVE" or "DEPART":
$ egrep 'timeInJail,((ARRIVE)|(DEPART))' prisonerd2024.log |
head -100
000000000012,LOG,thread 1 process 0,timeInJail,ARRIVE
000000000012,LOG,thread 0 process 0,timeInJail,ARRIVE
000000000013,LOG,thread 1 process 1,timeInJail,ARRIVE
000000000013,LOG,thread 0 process 1,timeInJail,ARRIVE
000000000013,LOG,thread 0 process 1,timeInJail,DEPART
000000000014,LOG,thread 1 process 0,timeInJail,DEPART
000000000014,LOG,thread 0 process 0,timeInJail,DEPART
000000000014,LOG,thread 1 process 2,timeInJail,ARRIVE
000000000014,LOG,thread 0 process 2,timeInJail,ARRIVE
000000000014,LOG,thread 1 process 0,timeInJail,ARRIVE
000000000014,LOG,thread 0 process 0,timeInJail,ARRIVE
000000000015,LOG,thread 1 process 3,timeInJail,ARRIVE
000000000015,LOG,thread 0 process 3,timeInJail,ARRIVE
000000000015,LOG,thread 0 process 3,timeInJail,DEPART
000000000016,LOG,thread 1 process 1,timeInJail,DEPART
000000000016,LOG,thread 1 process 2,timeInJail,DEPART
000000000016,LOG,thread 0 process 2,timeInJail,DEPART
000000000016,LOG,thread 1 process 0,timeInJail,DEPART
000000000016,LOG,thread 0 process 0,timeInJail,DEPART
000000000016,LOG,thread 1 process 4,timeInJail,ARRIVE
000000000016,LOG,thread 0 process 4,timeInJail,ARRIVE
000000000016,LOG,thread 0 process 4,timeInJail,DEPART
000000000016,LOG,thread 0 process 1,timeInJail,ARRIVE
000000000016,LOG,thread 1 process 1,timeInJail,ARRIVE
000000000016,LOG,thread 1 process 2,timeInJail,ARRIVE
000000000016,LOG,thread 0 process 2,timeInJail,ARRIVE
000000000016,LOG,thread 1 process 0,timeInJail,ARRIVE
000000000016,LOG,thread 0 process 0,timeInJail,ARRIVE
000000000016,LOG,thread 0 process 1,timeInJail,DEPART
000000000017,LOG,thread 1 process 5,timeInJail,ARRIVE
000000000017,LOG,thread 0 process 5,timeInJail,ARRIVE
000000000018,LOG,thread 1 process 3,timeInJail,DEPART
000000000018,LOG,thread 1 process 2,timeInJail,DEPART
000000000018,LOG,thread 0 process 2,timeInJail,DEPART
000000000018,LOG,thread 1 process 0,timeInJail,DEPART
000000000018,LOG,thread 0 process 0,timeInJail,DEPART
000000000018,LOG,thread 1 process 5,timeInJail,DEPART
000000000018,LOG,thread 0 process 5,timeInJail,DEPART
000000000018,LOG,thread 1 process 6,timeInJail,ARRIVE
000000000018,LOG,thread 0 process 6,timeInJail,ARRIVE
000000000018,LOG,thread 0 process 3,timeInJail,ARRIVE
000000000018,LOG,thread 1 process 3,timeInJail,ARRIVE
000000000018,LOG,thread 1 process 2,timeInJail,ARRIVE
000000000018,LOG,thread 0 process 2,timeInJail,ARRIVE
000000000018,LOG,thread 1 process 0,timeInJail,ARRIVE
000000000018,LOG,thread 0 process 0,timeInJail,ARRIVE
000000000018,LOG,thread 1 process 5,timeInJail,ARRIVE
000000000018,LOG,thread 0 process 5,timeInJail,ARRIVE
000000000018,LOG,thread 0 process 2,timeInJail,DEPART
000000000019,LOG,thread 1 process 4,timeInJail,DEPART
000000000019,LOG,thread 1 process 1,timeInJail,DEPART
000000000019,LOG,thread 1 process 6,timeInJail,DEPART
000000000019,LOG,thread 0 process 6,timeInJail,DEPART
000000000019,LOG,thread 1 process 5,timeInJail,DEPART
000000000019,LOG,thread 0 process 5,timeInJail,DEPART
000000000019,LOG,thread 1 process 7,timeInJail,ARRIVE
000000000019,LOG,thread 0 process 7,timeInJail,ARRIVE
000000000019,LOG,thread 0 process 4,timeInJail,ARRIVE
000000000019,LOG,thread 1 process 4,timeInJail,ARRIVE
000000000019,LOG,thread 0 process 1,timeInJail,ARRIVE
000000000019,LOG,thread 1 process 1,timeInJail,ARRIVE
000000000019,LOG,thread 1 process 6,timeInJail,ARRIVE
000000000019,LOG,thread 0 process 6,timeInJail,ARRIVE
000000000019,LOG,thread 1 process 5,timeInJail,ARRIVE
000000000019,LOG,thread 0 process 5,timeInJail,ARRIVE
000000000019,LOG,thread 0 process 1,timeInJail,DEPART
000000000020,LOG,thread 0 process 3,timeInJail,DEPART
000000000020,LOG,thread 1 process 3,timeInJail,DEPART
000000000020,LOG,thread 1 process 0,timeInJail,DEPART
000000000020,LOG,thread 0 process 0,timeInJail,DEPART
000000000020,LOG,thread 0 process 4,timeInJail,DEPART
000000000020,LOG,thread 1 process 4,timeInJail,DEPART
000000000020,LOG,thread 1 process 6,timeInJail,DEPART
000000000020,LOG,thread 0 process 6,timeInJail,DEPART
000000000020,LOG,thread 1 process 5,timeInJail,DEPART
000000000020,LOG,thread 0 process 5,timeInJail,DEPART
000000000020,LOG,thread 1 process 8,timeInJail,ARRIVE
000000000020,LOG,thread 0 process 8,timeInJail,ARRIVE
000000000020,LOG,thread 0 process 8,timeInJail,DEPART
000000000020,LOG,thread 0 process 3,timeInJail,ARRIVE
000000000020,LOG,thread 1 process 3,timeInJail,ARRIVE
000000000020,LOG,thread 1 process 0,timeInJail,ARRIVE
000000000020,LOG,thread 0 process 0,timeInJail,ARRIVE
000000000020,LOG,thread 0 process 4,timeInJail,ARRIVE
000000000020,LOG,thread 1 process 4,timeInJail,ARRIVE
000000000020,LOG,thread 1 process 6,timeInJail,ARRIVE
000000000020,LOG,thread 0 process 6,timeInJail,ARRIVE
000000000020,LOG,thread 1 process 5,timeInJail,ARRIVE
000000000020,LOG,thread 0 process 5,timeInJail,ARRIVE
000000000020,LOG,thread 0 process 4,timeInJail,DEPART
000000000021,LOG,thread 1 process 2,timeInJail,DEPART
000000000021,LOG,thread 1 process 7,timeInJail,DEPART
000000000021,LOG,thread 0 process 7,timeInJail,DEPART
000000000021,LOG,thread 1 process 6,timeInJail,DEPART
000000000021,LOG,thread 0 process 6,timeInJail,DEPART
000000000021,LOG,thread 1 process 5,timeInJail,DEPART
000000000021,LOG,thread 0 process 5,timeInJail,DEPART
000000000021,LOG,thread 1 process 9,timeInJail,ARRIVE
000000000021,LOG,thread 0 process 9,timeInJail,ARRIVE
000000000021,LOG,thread 0 process 2,timeInJail,ARRIVE
We can check the above penalty times
in state timeInJail by
looking at the log file. See times above.
processor.action =
[
["defect", "defect"],
["defect", "cooperate"],
["defect", "halfsy"],
["defect", "reciprocate"],
["halfsy", "cooperate"],
["reciprocate", "cooperate"],
["cooperate", "cooperate"],
["halfsy", "halfsy"],
["halfsy", "reciprocate"],
["reciprocate", "reciprocate"]
];
processor.penalty =
{
"defect" : {
"defect" : 2,
"cooperate" : 0
},
"cooperate" : {
"defect" : 3,
"cooperate" : 1
}
};