What’s going on in my program in Unix Services?

On Linux, starting a Python program is subsecond. On z/OS, running on zD&T (so emulated hardware) it takes about 2 seconds. I wondered if what was causing this – is my ZFS file system slow?

I used the Unix command

bpxtrace -o /tmp/trace -f format -c  python ac.py

to capture a trace.

This produced output like

       PID ASID TCB    Local time      System call           Additional trace
-  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  -  - 
     65589 0049 8FB2F8 08:27:13.722080 Call open             parms: 0000004D 
     65589 0049 8FB2F8 08:27:13.722714 Exit open             rv=00000004 
     65589 0049 8FB2F8 08:27:13.722741 Call fstat            parms: 00000004 
     65589 0049 8FB2F8 08:27:13.722785 Exit fstat            rv=00000000 
     65589 0049 8FB2F8 08:27:13.722817 Call lseek            parms: 00000004 
     65589 0049 8FB2F8 08:27:13.722824 Exit lseek            rv=00000000 
     65589 0049 8FB2F8 08:27:13.722836 Call lseek            parms: 00000004 
     65589 0049 8FB2F8 08:27:13.722883 Exit lseek            rv=00000000 
     65589 0049 8FB2F8 08:27:13.722896 Call lseek            parms: 00000004 
     65589 0049 8FB2F8 08:27:13.722901 Exit lseek            rv=00000000 

This is ok, but I want to know how long the calls took.

I wrote an ISPF Rexx script

/* REXX */ 
/* 
exec to extract the alias records from a catalog listing 
*/ 
ADDRESS ISPEXEC 
'ISREDIT MACRO (lines) ' 
"ISREDIT         (f) = LINENUM .ZLAST" 
sum = 0
do j = 3  by 2 to f 
   k = j + 1 
   "ISREDIT      ( bef) = LINE   " j 
   "ISREDIT      ( aft) = LINE   " k 
   parse var bef . 27 mm 29 . 30 ss 39 . 40 what 
   parse var aft . 27 am 29 . 30 as 39 
   before = 60 * mm    + ss 
   after  = 60 * am    + as 
   sum = sum + (after - before) 
   delta = format(after - before,1,6) 
   string = "== "delta what 
   "ISREDIT  LINE  (k) =  (string)" 
    
end 
say sum
exit 

running the Rexx script produced output in the file like

     65589 0049 8FB2F8 08:27:13.722080 Call open      
== 0.000630 Call open 
     65589 0049 8FB2F8 08:27:13.722741 Call fstat     
== 0.000050 Call fstat 
     65589 0049 8FB2F8 08:27:13.722817 Call lseek     
== 0.000000 Call lseek 

Using the ISPF commands

• X all
• f “==” all
• del all x
• sort 1 11

This gave

== 0.000000 Call lseek 
== 0.000000 Call lseek 
...
0.000820 Call close            parms: 00000005 00000000 00000000 05FC0119 
0.001450 Call cond_timed_wait  parms: 00000000 000F4240 00000001 00000000 20861040
0.002450 Call loadhfs          parms: 00000048 /u/tmp/zowet/colin/envz/lib/python3...
0.004200 Call loadhfs          parms: 00000008 CELQDCPP 00000000 0000010C 61E9F3F1
0.004310 Call loadhfs          parms: 00000007 CXXRT64 00000000 0000010C 61E9F3F1 
0.034780 Call mvsprocclp       parms: 00000100 00000000 00000000 00000000 
0.042970 Call mvsprocclp       parms: 00000100 2081D1D8 2086CC75 00000000 

There were nearly 500 lines in the output file. 400 entries were 100 microseconds or less. There were 6 entries taking longer than 1 millisecond.
My trace file was of duration 1.1 seconds. Adding up the individual times took 0.13 seconds, so it looks like the delays are not caused by the file system, and I need to look else where.