Problem with "Pipe" command.

[The Brit]

I have noticed a problem with the pipe command (or my use of it).     I have experienced this issue on and off, for a couple of years, however since it only appeared to be affecting me, and then only occasionally, it never made it up the priority ladder to the "lets see if we can get this resolved" level.

Now however, I have a report from one of our developers that he is experiencing the same problem.

basically, the problem is that the pipe command will just hang.      The Pipe Command in question is;

$ Pipe show license I64-run9 /usage | Search Sys$Input I64-RUN9 | (Read Sys$Input Line ; -

                    Free = f$elem(4," ",f$edit(Line,"COMPRESS")) ; define/job/NoLog Nfree &free)

Basically I use it to check the number of Licenses available at a given point in time.       I run the command periodically through the night time processing.   In order to avoid affecting (i.e. hanging) the business job streams, I run this as a separate batch job and write the results into a log, with timestamps.    I can then match up the timestamps to the business stuff.

The problem is that, for no clear reason, the command will hang the batchjob, after executing successfully several hundred times.   My initial thought was that it might have something to do with accessing the License DB, however I how have a second example which does not touch the license DB.   the second command is;

$    PIPE VLOG -B CUSTAUTHREC.DBL | SEARCH/NOHIGH SYS$PIPE "Locks:" | -

                     (READ SYS$PIPE LINE1 ; ASSIGN/JOB/NOLOG &LINE1 LOCK_INFO)

This exhibits the same behaviour, i.e. it executes several hundred times and then hangs.

Note that in both of these cases, the command hangs, there is no error, and Ctrl/Y is the only solution.

Our systems are bl860c blades running OpenVMS 8.3-1H1.   

Does anyone have any ideas??

thanks Dave.

[Bob Blunt]

Dave, are you looping and re-executing the command in batch until it hangs?  I wasn't able to tell how you're seeing the problem manifest itself from your description.  If you're looping I'd check for resource exhaustion.  If not... wow.  I know that we've seen some commands over the years that were sensitive to, no only, system configuration but the allocation of some obscure system parameters...  SHOW DEVICE starting late in V5 for instance.

bob

[John McL]

What state is the process and subprocesses in when it all hangs?

Are you running out of some quota?

[Volker Halle]

Dave,

if 'the pipe command hangs' go into SDA and look at the process state of the main process and the subprocess. Try commands like: SHOW PROC/LOCK and SHOW PROC/CHAN or use the PWAIT$SDA extension from Ian Miller.

Volker.

[The Brit]

   I have attached the com file which exhibits the problem, and I have added the information requested by Volker.     When the process hangs, there are no sub-processes there, only the parent.

Brief description:   We use PVCS for Code Management.    The pipe command uses the "vlog" command to check every program in the source directory (TSS:), for "locks", indicating that that source is currently checked out.   There are ~1800 source files in the directory.

As can be seen from the script, it is a simple loop, so it could be a quota or resource issue, in which case I need to be able to identify the quota/resource involved.    

Note, after the script has hung, it does not respond to a Ctrl/Y, I have to kill the process from a separate session.

TIA for any suggestions.

Dave.

[The Brit]

Additional:

The script rarely makes it all the way to the end, however there is no consistency regarding where it will hang.   Sometimes after a few hundred loops, sometimes after many hundred loops.

This makes me think it is not a "process" quota since I have tried running the script as the first item after login several times, with the same result.    Running with a clean quota slate does not get any further into the script before hanging.     In fact the percentage of source code files which are checked seems quite random.

I also tried putting a 0.25sec wait into the loop, made no significant difference.

When monitoring continuously, I did notice quite a few (say ~5%)  MWAIT states ticking through (less when the "wait" was put in the loop).    This difference however, might have just been and optical illusion.

Dave

[Volker Halle]

Dave,

the PIPE commands will be executed in a sub-process. The main process and the sub-process communicate via MPA: (mailbox-like) devices. If the subprocess is gone and the main process is waiting, what happened to the sub-process ? Can you check the accounting records for the sub-process, there should be ONE for each execution of the pipe command.

Also check for non-fatal bugcheck in ERRLOG.SYS, which may make the subprocess disappear without returning status back to the creator process.

Volker.

[Hoff]

All that the pipe command is saving here is a temporary file, and it can (as is the case here) add complexity and debugging difficulty; it's common to see problems introduced with pipe commands.  

DCL error handling isn't stellar.

Given there's no API for LMF information (f$getlui or f$getlmf or sys$getlui or sys$getlmf or whatever), brute-force parsing is the only option.  Get rid of the pipe, and use a small command procedure and a temporary file.

You'll get a log (if you want it), and (with SET NOON at the top) you'll have better error reporting and recovery.

I'd guess that you're colliding with LMF activity, but that's not entirely clear.

(Whoa, is this forum software buggy...  How can it mess up cut-n-paste?  And what is this "Your post has been changed because invalid HTML was found in the message body. The invalid HTML has been removed. Please review the message and submit the message when you are satisfied." stuff?)

[The Brit]

Volker,

     I have attached the last couple of hundred lines from the accounting file.  the parent process is "200A9".      I'm not sure what to make of it.     The sub-processes seem to be in groups of 3, which would make sense since the pipe command has 3 parts, however sub-processes 2 and 3 seem to terminate with;

%SYSTEM-F-EXITFORCED, forced exit of image or process by SYS$DELPRC

Which seems bad to me (but maybe it's not!) (helpless shrug of shoulders)

The errolog doesnot appear to have any entries in it for today or yesterday, except for a timestamp.

Dave

[John Gillings · Accepted solution]

Dave,

   PIPE can be ugly. If they're unbalanced, the processes effectively synchronise using RWMBX, that is, if the reader stage can't keep up, the writer will go RWMBX until the pipeline is cleared. This is VERY VERY expensive.

I don't know what the output of VLOG looks like, but if the SEARCH stage generates more than one line of output, it's possible that the SEARCH subprocess hasn't completed by the time the READ+DEFINE stage exits, at which time the earlier pipe stages will be $DELPRCed. If one of them was RWMBX at the time, that MIGHT upset the synchronisation back to the master process so it's left waiting for a terminated process.

Also be aware that in batch mode, the way PIPE SYS$OUTPUT works is quite different from the interactive case. There are some timing bugs involved that OpenVMS engineering seems reluctant to do anything about (do you have any stray DCL$OUTPUT*.LOG files?)

If your objective is to generate a log file of time stamps, try restructuring to leave each stage running longer and doing more. Something like:

$ PIPE @VLOG_LOOP | SEARCH/NOHIGH SYS$PIPE "Locks:" | @LOGLINES | APPEND LOGFILE SYS$PIPE

where, VLOG_LOOP looks like:

NEXT_FILE:
$  FILESPEC = F$SEARCH("TSS:*.*",1)
$  IF FILESPEC.EQS."" THEN GOTO NO_MORE
$  FILENAME = F$PARSE(FILESPEC,,,"NAME","SYNTAX_ONLY") + -
              F$PARSE(FILESPEC,,,"TYPE","SYNTAX_ONLY")
$  WRITE SYS$OUTPUT FILENAME
$  VLOG -B 'FILENAME'
$GOTO NEXT_FILE

and LOGLINES might look like:

$ LOOP: READ/END=EndLoop SYS$PIPE LINE
$   WRITE SYS$OUTPUT F$TIME(),LINE
$ GOTO LOOP
$ EndLoop:

My preference would be to code all the stages in the same procedure and use a branch on P1 to select which code to execute.

PIPEs are useful, but can get ugly, and sometimes incredibly slow. I've got plenty of procedures that run for months with both transient and long term pipes.

[John McL]

Not potential solutions but thoughts about investigation

1. Your second example is

$    PIPE VLOG -B CUSTAUTHREC.DBL | SEARCH/NOHIGH SYS$PIPE "Locks:" | -

                     (READ SYS$PIPE LINE1 ; ASSIGN/JOB/NOLOG &LINE1 LOCK_INFO)

Is there any chance that LINE1 might contain an embedded space or tab when you do the ASSIGN?  (Similarly with you main example, which is an F$ELEMENT(4, ? where I can't tell if the ? as I show it is a space or a tab - could the other character be embedded here?)

2. Also, the & symbol puts a pipe into the background (like a SPAWN/NOWAIT).  What's not so clear from VMS Help is whether this applies when there's no space following the '&'.  Maybe it's worth modifying that line to test it.

3. Does the CPU load have any relationship to when your cycling job terminates? I hope you are running some kind of monitoring tool to provide this answer, but even if you don't your opinion about any relationship might be useful

[John Gillings]

re: John McL

>2. Also, the & symbol puts a pipe into the background (like a SPAWN/NOWAIT). 

>What's not so clear from VMS

>Help is whether this applies when there's no space following the '&'. 

>Maybe it's worth modifying that line to test it

In this case the ampersand "&" is not a PIPE separator, it's a symbol substitution operator. This syntax has been present since VMS V1.0, but is rather obscure (and difficult to find in the documentation - the only mention I can find is in the OpenVMS User's Manual, section 12.12.2).

The ampersand substitution is required in this case so the symbol substitution is performed in the context of the pipe thread, after it has been given a value, rather than in the context of the main process at the time the PIPE command is parsed.