Why does this take more as a second

55 views
Skip to first unread message

Cecil Westerhof

unread,
Sep 5, 2022, 7:59:06 AMSep 5
to
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

unread,
Sep 5, 2022, 10:28:16 AMSep 5
to
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

unread,
Sep 5, 2022, 11:44:08 AMSep 5
to
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

unread,
Sep 5, 2022, 1:30:05 PMSep 5
to
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.

Reply all
Reply to author
Forward
0 new messages