Log file sequence anomolies

[RichardAD]

I am parsing the SAS log to extract data about writing files: the filename, lines written summary and cpu and real time. SCAPROC is not available to me because it is already running by a system that runs my code.

The log file issue is that most frequently the cpu & real time loglines are last in a sequence of messages, but sometimes the cpu & real time messages come before lines written summary part.

For example: The log file normally has

NOTE: The file library OUT is:
      Directory=#####,
      Owner Name=webtrust,Group Name=webtrust,
      Access Permission=drwxrwxrwx,
      Last Modified=24Jan2025:07:01:26

NOTE: The file OUT(*****.csv) is:
      Filename=#####/*****.csv,
      Owner Name=%%%%%%%%,Group Name=webtrust,
      Access Permission=-rw-rw-rw-,
      Last Modified=24Jan2025:07:01:26

NOTE: A total of 5509 records were written to the file library OUT.
      The minimum record length was 80.
      The maximum record length was 125.
NOTE: 5509 records were written to the file OUT(*****.csv).
      The minimum record length was 80.
      The maximum record length was 125.
NOTE: There were 5508 observations read from the data set INP.######.
NOTE: DATA statement used (Total process time): *** Most of the time these 3 lines are last in the sequence of log messages ***
      real time 0.83 seconds 
      cpu time 0.82 seconds

but infrequently there are cases in which the cpu and real time come before the summary of the lines written

NOTE: The file library OUT is:
      Directory=#####,
      Owner Name=webtrust,Group Name=webtrust,
      Access Permission=drwxrwxrwx,
      Last Modified=24Jan2025:07:01:26

NOTE: The file OUT(*****.csv) is:
      Filename=#####/*****.csv,
      Owner Name=%%%%%%%%,Group Name=webtrust,
      Access Permission=-rw-rw-rw-,
      Last Modified=24Jan2025:07:01:26

NOTE: DATA statement used (Total process time): *** Normally these 3 lines are last in the sequence of log messages ***
      real time           0.83 seconds
      cpu time            0.82 seconds
      
NOTE: A total of 5509 records were written to the file library OUT.
      The minimum record length was 80.
      The maximum record length was 125.
NOTE: 5509 records were written to the file OUT(*****.csv).
      The minimum record length was 80.
      The maximum record length was 125.
NOTE: There were 5508 observations read from the data set INP.######.

Any ideas why this happens?

[quickbluefish]

it's a little bit hard to tell what's going on without having OPTIONS mprint; turned on. I would suggest doing that and re-posting the log.

[RichardAD]

There is no macro involved. The code being executed is generated in a data _null_ and written to a temp file which is then %included.

[Tom]

Then either set the SOURCE2 option or add the /SOURCE2 option to the %INCLUDE statement.

[RichardAD]

The generated code is a code-gen block, such as below. One per dataset in a library

1448      +data _null_ ;
1449      +  file out (<dataset>.csv) dlm=',' termstr=crlf ;
1450      +  if _n_ = 1 then
SYMBOLGEN:  Macro variable SAS2CSV_COL_NAMES resolves to 
            <comma-separated-list-of-column-names>
1450     !+                  put "&sas2csv_col_names" ;
1451      +  set inp.<dataset> ;
1452      +  format _character_ $quote32767. ;
1453      +  put (_all_) (:) ;
1454      +run ;

The core of the open-code generator is

data _null_ ;
  file gencode ;
  do z = 0 by 0 until (z) ;
    set inp_tables end = z ;
    put "proc sql noprint ;"
      / "  select name into :sas2csv_col_names separated by ',' from sas2csv_inp_columns"
      / "  where  upcase (memname) = " qmemname "order varnum"
      / "  ;"
      / "quit ;"
      / ;
    put "data _null_ ;"
      / "  file out (" lmemname +(-1)".csv) dlm=',' termstr=crlf ;"
      / '  if _n_ = 1 then put "&sas2csv_col_names" ;'           /* header row */
      / "  set inp." lmemname ";"
      / '  format _character_ $quote32767. ;'
      / "  put (_all_) (:) ;"                                    /* data rows */
      / "run ;"
      / ;
  end ;
run ;
%inc gencode / source2 ;

[Tom]

Does having the %INCLUDE writing the source code prevent the re-ordering of the blocks of log lines?

You might also try running with the logparm option set to prevent buffering of writes to the SAS log and see if that effects the ordering of the blocks of lines.

-logparm 'write=immediate'

Can you test without the process that in invoking SCAPROC?  Perhaps that is what is interfering with the ordering of the blocks of lines.

Ultimately you will probably need to ask SAS technical support to look into this issue.