Trace-to-file feature

[Fish-Git]

---

Note: this issue is closely related to issue #32: "Instruction registers display is buggy/unreliable".

---

Instruction and I/O tracing is currently very slow (introduces a significant performance impact) due to, I believe, the fact that the current implementation always immediately formats and displays the trace information directly to the console while tracing is active (which is very inefficient not only because formatting a message itself is inefficient, but also because our entire message handling is itself incredibly inefficient, passing formatted messages through a pipe, etc).

I suspect the performance of instruction and I/O tracing would be dramatically improved if we would instead simply write the raw information to a disk file which could then be processed by an offline utility to selectively display the desired information.

[Fish-Git]

IT'S WORKING!   :-D

I only have the instruction tracing part of it working right now, but it's working great!  :)

And WOW does it ever help speed things up! I'll try to get some more precise numbers for you, but as a quick test I did an auto-trace of a z/OS IPL for 10,000 instructions, and doing it the old fashioned/current way (where each executed instruction is displayed on the HMC as the guest is running) took about 21 seconds, whereas using my new tf ("tracefile") command to just write all of the raw information to a disk file instead took only ONE SECOND!  :)

Doing an instruction trace is still going to slow down the guest considerably even when tracing to a file, but with my new trace-to-file functionality at least now it doesn't slow it down as much.

So yeah, I've made some good progress.

Something else I still need to do too is design some additional selection options into the tracefile print utility (called tfprint). Right now you can only select records by CPU or CPU range. I'd like to eventually provide the ability to select by time range as well (or possibly even by storage address, but I haven't decided on that yet since I think it might be a bitch to code).

I would also like to eventually do the same thing for I/O tracing too, but I think that can come later.

But things are looking up!  :)

Let me know if any of you are interested in giving it a try and I'll upload the patch for you. It's quite large (138K).

Thanks!

[Fish-Git]

Let me know if any of you are interested in giving it a try and I'll upload the patch for you. It's quite large (138K).

Or should I create a fork and publish it there? Hmmmm... What do you think?

[Fish-Git]

Okay, here are some hard numbers from a quick test I just did:

Testing parameters:

• z/OS 2.5 IPL
• Automatic trace of 100,000 instructions: t+- BEG=2225211128 AMT=100000
• Trace-to-file command: tf on max=10g "name=C:\Users\Fish\Downloads\trace.dat"
• "tfprint" print trace file command: tfprint.exe C:\Users\Fish\Downloads\trace.dat -r regsfirst > C:\Users\Fish\Downloads\trace.txt 2>&1

Results:

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

Test z/OS 2.5 IPL using native HMC panel:

  tf (trace to file):

    20:03:49 HHC02370I Automatic tracing started at instrcount 2225211128 (BEG+0)
    20:03:53 HHC02371I Automatic tracing stopped at instrcount 2225311128 (AMT+0)

    duration       = 4 seconds
    instr rate     = 25000/sec
    logfile size   = 45K
    tracefile size = 50.0MB

  normal (trace to HMC):

    20:10:36 HHC02370I Automatic tracing started at instrcount 2225211146 (BEG+18)
    20:14:00 HHC02371I Automatic tracing stopped at instrcount 2225311146 (AMT+0)
    20:14:00  IEE178I AUTOMATIC RECOVERY IS IN PROGRESS
    20:14:00  NO OPERATOR ACTION IS REQUIRED.
    20:14:00  PROCESSOR (0001) DETECTED AN EXCESSIVE DISABLED SPIN LOOP
    20:14:00  WAITING FOR LOCK RELEASE                  FROM PROCESSOR (0005).
    20:14:00  AUTOMATIC RECOVERY ACTION IS ABEND

    duration     = 204 seconds   (3 minutes, 24 seconds)
    instr rate   = 490/sec       (!!!!)
    logfile size = 109MB

  tf is OVER 50 TIMES faster!

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

Test z/OS 2.5 IPL using HercGUI:

  tf (trace to file):

    20:33:23.443 HHC02370I Automatic tracing started at instrcount 2225211177 (BEG+49)
    20:33:26.317 HHC02371I Automatic tracing stopped at instrcount 2225311177 (AMT+0)

      duration         = 3 seconds
      instr rate       = 33333/sec
      logfile size     = 47K
      tracefile size   = 49.6MB
      trace print size = 117MB

  normal (trace to HMC):

    20:40:46.081 HHC02370I Automatic tracing started at instrcount 2225211214 (BEG+86)
    20:41:17.062 HHC02371I Automatic tracing stopped at instrcount 2225311214 (AMT+0)

      duration     = 31 seconds (*)
      instr rate   = 3225/sec
      logfile size = 114MB

  tf is OVER 10 TIMES faster!

  (*)  And tracing to the HMC is also over 6.5 times faster when HercGUI is used too!

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

I would consider that to be fairly impressive!  :)

Comments?

Attachment:  .zip file of all log files, trace file, and resulting tfprint of trace file = 26MB:

• trace.zip

Warning!  Total UNZIPPED size of all files = approximately 342MB!
 

[Fish-Git]

FYI: There was a minor glitch (bug) in my tfprint utility that was printing the wrong processor-type string (e.g. if engine 4 was defined as a ziip, it was printing "CP04" instead of "IP04"). This has since been fixed.

[Fish-Git]

UPDATE: I have virtually all of the instruction tracing to file and the tfprint (tracefile print) utility coded and tested and it seems to be working quite well.

Am currently working on trying to incorporate I/O device tracing into the Trace to File design as well.

[Fish-Git]

Closed by commit 598c467.

Please give it a try and tell me what you think!

Here's the help information for both the new 'tf' command as well as the new 'tfprint' utility:

HHC01603I help tf
HHC01603I 
HHC01602I Command               Description
HHC01602I ----------------      -------------------------------------------------------
HHC01602I tf                   *Define trace-to-file parameters
HHC01603I 
HHC01603I Format:
HHC01603I 
HHC01603I    tf  [ OFF | ON ] [ "FILE=filename" ] [ MAX=nnnS ] [ STOP | NOSTOP ]
HHC01603I 
HHC01603I Defines the parameters for instruction and/or ccw tracing to an output
HHC01603I file. Note that this command only enables/disables tracing to a file;
HHC01603I you will still need to enable instruction and/or ccw tracing separately
HHC01603I via the 't+' and/or 't+dev' command(s).
HHC01603I 
HHC01603I ON or OFF enables or disables tracing to a file. If ON is specified
HHC01603I then FILE= is required if not already defined by a previous command.
HHC01603I Enclose the entire option name and value within double quotes if it
HHC01603I contains any blanks (e.g. "FILE=my trace file").
HHC01603I 
HHC01603I MAX= specifies the desired maximum size the trace file is allowed to
HHC01603I grow to. Specify the value as "nnnM" for megabytes or "nnnG" for
HHC01603I gigabytes, where 'nnn' is the maximum number of megabytes/gigabytes
HHC01603I in size the file is allowed to grow to. Once the maximum is reached,
HHC01603I both tracefile tracing as well as all instruction and ccw tracing are
HHC01603I disabled. This prevents instruction and/or ccw tracing from continuing
HHC01603I to be traced but to the hardware panel instead once the limit has been
HHC01603I reached. Use the NOSTOP option to disable this behavior and allow the
HHC01603I instruction and/or ccw tracing to continue, but to the hardware panel
HHC01603I instead once the limit has been reached. The default is STOP/NOCONT.
HHC01603I 
HHC01603I OPEN/CLOSE or NOCONT/CONT may be used in lieu of ON/OFF or STOP/NOSTOP.
HHC01603I Specify the command without any arguments to display current values.
HHC01603I 

HHC02499I Hercules utility tfprint - Print Trace File Utility - version 4.6.0.10864-SDL-DEV-ga764beda
HHC01414I (C) Copyright 1999-2023 by Roger Bowler, Jan Jaeger, and others
HHC01417I ** The SoftDevLabs version of Hercules **
HHC01415I Build date: Jan 11 2023 at 00:07:19

HHC03217I Args:

HHC03201E Missing input-file specification
HHC00007I Previous message from function 'process_args' at tfprint.c(3149)

HHC03200I Usage:  tfprint  [options...] tracefile
HHC03200I
HHC03200I        [-i|--info]
HHC03200I        [-c|--cpu hh[[-hh][,hh]]
HHC03200I        [-r|--traceopt TRADITIONAL|REGSFIRST|NOREGS]
HHC03200I        [-n|--count nnnnnn[[-nnnnnn]|[.nnn]]
HHC03200I        [-e|--msg nnnnn[,nnnnn]
HHC03200I        [-s|--storage V|R:hhhhhh[[-hhhhhh]|[.hhh]]
HHC03200I        [-d|--date YYYY/MM/DD-YYYY/MM/DD
HHC03200I        [-t|--time HH:MM:SS.nnnnnn-HH:MM:SS.nnnnnn
HHC03200I        [-o|--opcode hhhhhhhh[,hhxxhhxxhhhh]
HHC03200I        [-m|--msglvl xxxxx
HHC03200I        [-u|--unit uuuu[[-uuuu]|[.nnn]]
HHC03200I        [-p|--codepage zzzzzzzz
HHC03200I
HHC03200I   -i   Print only TFSYS header information then exit
HHC03200I   -c   Print only specified CPU(s)
HHC03200I   -r   Print registers trace option
HHC03200I   -n   Print only records nnnnnn to nnnnnn (by count)
HHC03200I   -e   Print only messages with specified message number
HHC03200I   -s   Print only instructions that reference or modify
HHC03200I        the specified 'V'irtual or 'R'eal storage range
HHC03200I   -d   Print only records within specified date range
HHC03200I   -t   Print only records within specified time range
HHC03200I   -o   Print only specified instruction(s) (by opcode)
HHC03200I        Only as many bytes are checked as are specified
HHC03200I        Use 'x' as wildcard for nibbles not to be checked
HHC03200I   -m   Modify Hercules 'msglvl' setting
HHC03200I   -u   Print only trace records for specified I/O unit(s)
HHC03200I   -p   Use EBCDIC/ASCII codepage conversion table zzzzzzzz