This was used for NA16294922. Here is the Email about how to use it:

--------------------

Fertig! :)

 

I managed to find a usable filter which covers about 5-6 seconds of trace so it should be enough for the proposed purpose. Ok, so find the script attached.

 

@Cc: maybe read the thread bottom up to understand the background  it is about WD0 restarts on VMWare despite all Reservations are OK. So we suspect the VM still gets interrupted for too long from time to time and this here is supposed to be a tracing possibility to prove that theory.

 

HowTo use  just copy to the Linux Platform and unpack via the command unzip vmkerneltrace.zip.

 

Then you get in the current directory the .sh script and this should be called inside a screen session and afterwards detach the session so like this:

 

screen -S kernel_trace

bash vmkerneltrace.sh

 

and now press CTRL-a and then d in order to detach from the screen session.

 

Then close the putty/terminal. The script will continue to run in the background. It will also log all output to this logfile : /var/log/vmkerneltrace/vmkerneltrace.log

 

The output with two caught restarts looks like this:

 

ECOSIMPLEX0:~ # bash vmsc.sh

vmsc.sh started and logging also this output to /var/log/vmkerneltrace/vmkerneltrace.log

Activate tracer nop with 20480KB buffer

Wed Jan 16 02:56:00 EET 2019

CCA RESTART detected. Kernel Trace stopped.

[Jan 16 02:56:00] START BOOT VERSION H062-Q-a24 (FLASH 2 LOADED) CARD TYPE: DSCXL-X300

Tracer stopped : 0

kernel trace no=1 written to /var/log/vmkerneltrace at 20190116-025608

-rw------- 1 root root 143108765 Jan 16 02:56 /var/log/vmkerneltrace/kerneltrace.nop.20190116-025608.log

trace has been restarted. Will now analyze the trace file and determine ADP and SWU process interruptions :

Stat for qemu-kvm process PID : 12124

   Biggest Gap (uS) : 113515

           qemu-kvm-12124 [002] 394768.281807: sys_exit: NR 23 = 1

Stat for qemu-kvm process PID : 12748

   Biggest Gap (uS) : 11284

           qemu-kvm-12748 [000] 394774.111615: sys_exit: NR 23 = 1

Stat for qemu-kvm process PID : 12761

   Biggest Gap (uS) : 319612

           qemu-kvm-12761 [002] 394767.978061: sys_exit: NR 202 = 0

Stat for qemu-kvm process PID : 12900

   Biggest Gap (uS) : 125896

           qemu-kvm-12900 [002] 394767.872581: sys_exit: NR 23 = 1

Stat for qemu-kvm process PID : 13248

   Biggest Gap (uS) : 209326

           qemu-kvm-13248 [002] 394768.511362: sys_exit: NR 202 = 0

Stat for qemu-kvm process PID : 15591

   Biggest Gap (uS) : 11174

           qemu-kvm-15591 [000] 394774.083984: sys_exit: NR 202 = 0

will now compress /var/log/vmkerneltrace/kerneltrace.nop.20190116-025608.log in order to save HD space ...

-rw------- 1 root root 7256853 Jan 16 02:56 /var/log/vmkerneltrace/kerneltrace.nop.20190116-025608.log.bz2

Wed Jan 16 02:57:30 EET 2019

ADP RESTART detected. Kernel Trace stopped.

[Jan 16 02:57:30] START BOOT VERSION H062-Q-a24 (FLASH 2 LOADED) CARD TYPE: DSCXL-X300

Tracer stopped : 0

kernel trace no=2 written to /var/log/vmkerneltrace at 20190116-025732

-rw------- 1 root root 141643278 Jan 16 02:57 /var/log/vmkerneltrace/kerneltrace.nop.20190116-025732.log

trace has been restarted. Will now analyze the trace file and determine ADP and SWU process interruptions :

Stat for qemu-kvm process PID : 12124

   Biggest Gap (uS) : 89473

           qemu-kvm-12124 [002] 394859.831814: sys_exit: NR 23 = 1

Stat for qemu-kvm process PID : 12761

   Biggest Gap (uS) : 159105

           qemu-kvm-12761 [002] 394858.977242: sys_exit: NR 202 = 0

Stat for qemu-kvm process PID : 12900

   Biggest Gap (uS) : 132317

           qemu-kvm-12900 [002] 394859.291077: sys_exit: NR 23 = 1

Stat for qemu-kvm process PID : 13240

   Biggest Gap (uS) : 5466

           qemu-kvm-13240 [001] 394863.831777: sys_exit: NR 23 = 1

Stat for qemu-kvm process PID : 13248

   Biggest Gap (uS) : 109848

           qemu-kvm-13248 [002] 394859.342798: sys_exit: NR 202 = 0

will now compress /var/log/vmkerneltrace/kerneltrace.nop.20190116-025732.log in order to save HD space ...

-rw------- 1 root root 7300519 Jan 16 02:58 /var/log/vmkerneltrace/kerneltrace.nop.20190116-025732.log.bz2

 

A restart means any new BOOTING of any RMX Qemu VM, so also if one would reset the APD or CC via AMO EXE-REST then the kernel trace would be stopped and evaluated. So this can be used only to check that the trace in in place and collecting information as expected.

 

The kernel traces are stored compressed inside same dir like the logfile. The tool also evaluates on the spot the trace and calculates the so-called biggest gap for all QEMU Threads. So for e.g. something like this (taken from above):

 

Stat for qemu-kvm process PID : 12900

   Biggest Gap (uS) : 132317

           qemu-kvm-12900 [002] 394859.291077: sys_exit: NR 23 = 1

 

Means that the QEMU process with PID 12900 during the last 5 seconds before the RMX restart occurred was never IDLE or PAUSED or simply NOT SCHEDULED or NOR RUNNING for anytime longer than  132317 microseconds.

 

The hypothesis in the VMWare case is that we will see very big interruptions, so now you should know what to check for.

 

Note: in the above output there are 5 QEMU Threads. This is normal. I do not know exactly which are all threads inside QEMU process (I have not checked it) but the above measurement should provide enough data for a first analysis.

I used a Simplex on EcoServer for the above outputs.

 

Regards,

   Mihai
   