This is part of a tclsh script that I am running as a systemd service
in Linux.

I have the following proc (waitMinutes is a proc I defined to wait for
the begin of a minute):
proc getVmstatFp {} {
puts "Wait for begin minute"
waitMinutes 1
puts "Starting vmstat run"
set count [expr {1441 - [getMinuteInDay]}]
set command "|env TZ=UTC vmstat -n -S M -t ${::runLength} ${count}"
set vmstat [open ${command} RDONLY]
# The first three lines need to be skipped
# First two are header, third is average
for {set i 0} {${i} < 3} {incr i} {
gets ${vmstat}
}
return ${vmstat}
}

It is used in the following loop:
while {True} {
set vmstat [getVmstatFp]
# Get and save lines until the end of the day
# The reason is that after a bit more as a day vmstat goes out of sync
while {-1 != [gets ${vmstat} line]} {
saveVmstatInfo ${line}
}
puts "Stopped vmstat run"
close ${vmstat}
}

Sometimes there is two seconds between:
puts "Stopped vmstat run"
and:
puts "Wait for begin minute"

The first could be on the end of the second and the second at the
begin of a second, but that still means that there is more as a second
between those two. That seems a lot of time for the close.
Is something wrong here, or is this normal?
(Most of the time the two statements are executed in the same second.)

--
Cecil Westerhof
Senior Software Engineer
LinkedIn: http://www.linkedin.com/in/cecilwesterhof

Cecil Westerhof <Cecil@decebal.nl> wrote:
> This is part of a tclsh script that I am running as a systemd service
> in Linux.
>
> set command "|env TZ=UTC vmstat -n -S M -t ${::runLength} ${count}"
> set vmstat [open ${command} RDONLY]
> ...
> close ${vmstat}
>
> Sometimes there is two seconds between:
> puts "Stopped vmstat run"
> and:
> puts "Wait for begin minute"
>
> The first could be on the end of the second and the second at the
> begin of a second, but that still means that there is more as a second
> between those two. That seems a lot of time for the close.
> Is something wrong here, or is this normal?
> (Most of the time the two statements are executed in the same second.)

From "man n close":

If channelId is a blocking channel for a command pipeline then
close waits for the child processes to complete.

You are closing a command pipeline, and the code you show did not set
non-blocking mode. The extra time you are seeing is probably vmstat
sleep jitter (i.e., it sometimes takes vmstat an extra second before it
learns its stdout has disappeared and exits).

Rich <rich@example.invalid> writes:

> Cecil Westerhof <Cecil@decebal.nl> wrote:
>> This is part of a tclsh script that I am running as a systemd service
>> in Linux.
>>
>> set command "|env TZ=UTC vmstat -n -S M -t ${::runLength} ${count}"
>> set vmstat [open ${command} RDONLY]
>> ...
>> close ${vmstat}
>>
>> Sometimes there is two seconds between:
>> puts "Stopped vmstat run"
>> and:
>> puts "Wait for begin minute"
>>
>> The first could be on the end of the second and the second at the
>> begin of a second, but that still means that there is more as a second
>> between those two. That seems a lot of time for the close.
>> Is something wrong here, or is this normal?
>> (Most of the time the two statements are executed in the same second.)
>
> From "man n close":
>
> If channelId is a blocking channel for a command pipeline then
> close waits for the child processes to complete.
>
> You are closing a command pipeline, and the code you show did not set
> non-blocking mode. The extra time you are seeing is probably vmstat
> sleep jitter (i.e., it sometimes takes vmstat an extra second before it
> learns its stdout has disappeared and exits).

But when I am closing the process it is already finished. It still can
happen then?
It is not really important, but I was just wondering. (When I see
something 'strange', I like to know the reason for it.) I think I will
keep it this way, because with non-blocking I do not get an error.
Should never happen, but if the 'impossible' happens, I want to know
about it.

--
Cecil Westerhof
Senior Software Engineer
LinkedIn: http://www.linkedin.com/in/cecilwesterhof

Cecil Westerhof <Cecil@decebal.nl> wrote:
> Rich <rich@example.invalid> writes:
>
>> Cecil Westerhof <Cecil@decebal.nl> wrote:
>>> This is part of a tclsh script that I am running as a systemd service
>>> in Linux.
>>>
>>> set command "|env TZ=UTC vmstat -n -S M -t ${::runLength} ${count}"
>>> set vmstat [open ${command} RDONLY]
>>> ...
>>> close ${vmstat}
>>>
>>> Sometimes there is two seconds between:
>>> puts "Stopped vmstat run"
>>> and:
>>> puts "Wait for begin minute"
>>>
>>> The first could be on the end of the second and the second at the
>>> begin of a second, but that still means that there is more as a second
>>> between those two. That seems a lot of time for the close.
>>> Is something wrong here, or is this normal?
>>> (Most of the time the two statements are executed in the same second.)
>>
>> From "man n close":
>>
>> If channelId is a blocking channel for a command pipeline then
>> close waits for the child processes to complete.
>>
>> You are closing a command pipeline, and the code you show did not set
>> non-blocking mode. The extra time you are seeing is probably vmstat
>> sleep jitter (i.e., it sometimes takes vmstat an extra second before it
>> learns its stdout has disappeared and exits).
>
> But when I am closing the process it is already finished. It still can
> happen then?

Unknown -- but this is most likely the explanation. Something taking
just a bit longer during the close.

> It is not really important, but I was just wondering. (When I see
> something 'strange', I like to know the reason for it.) I think I will
> keep it this way, because with non-blocking I do not get an error.
> Should never happen, but if the 'impossible' happens, I want to know
> about it.

To dig deeper you'd have to strace (with the follow forks option) and
start trying to piece together the actual order of events.