Why does this take more as a second

[Cecil Westerhof]

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

[Rich]

Cecil Westerhof <Ce...@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).

[Cecil Westerhof]

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.

[Rich]

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.