Jak mogę wyliczyć fajkę?

Chcę timepolecenia składającego się z dwóch oddzielnych poleceń z jednym wyjściem potokowym do drugiego. Weźmy na przykład dwa poniższe skrypty:

$ cat foo.sh
#!/bin/sh
sleep 4

$ cat bar.sh
#!/bin/sh
sleep 2

Jak mogę timezgłosić czas foo.sh | bar.sh(i tak, wiem, że fajka nie ma tutaj sensu, ale to tylko przykład)? Działa zgodnie z oczekiwaniami, jeśli uruchamiam je sekwencyjnie w podpowłoce bez instalacji:

$ time ( foo.sh; bar.sh )

real    0m6.020s
user    0m0.010s
sys     0m0.003s

Ale nie mogę go uruchomić podczas instalacji:

$ time ( foo.sh | bar.sh )

real    0m4.009s
user    0m0.007s
sys     0m0.003s

$ time ( { foo.sh | bar.sh; } )

real    0m4.008s
user    0m0.007s
sys     0m0.000s

$ time sh -c "foo.sh | bar.sh "

real    0m4.006s
user    0m0.000s
sys     0m0.000s

Przeczytałem podobne pytanie ( Jak uruchomić czas na wielu poleceniach ORAZ zapisać czas wyjściowy do pliku? ), A także wypróbowałem samodzielny timeplik wykonywalny:

$ /usr/bin/time -p sh -c "foo.sh | bar.sh"
real 4.01
user 0.00
sys 0.00

To nawet nie działa, jeśli utworzę trzeci skrypt, który uruchamia tylko potok:

$ cat baz.sh
#!/bin/sh
foo.sh | bar.sh

A potem czas, że:

$ time baz.sh

real    0m4.009s
user    0m0.003s
sys     0m0.000s

Co ciekawe, nie wydaje się, że timekończy się natychmiast po wykonaniu pierwszego polecenia. Jeśli zmienię bar.shna:

#!/bin/sh
sleep 2
seq 1 5

I timeznowu spodziewałem się, że timewydruk zostanie wydrukowany przed, seqale nie jest to:

$ time ( { foo.sh | bar.sh; } )
1
2
3
4
5

real    0m4.005s
user    0m0.003s
sys     0m0.000s

Wygląda na to, timeże nie liczy czasu wykonania bar.shpomimo oczekiwania na zakończenie przed wydrukowaniem raportu ¹ .

Wszystkie testy zostały uruchomione w systemie Arch i przy użyciu wersji bash 4.4.12 (1). Mogę użyć bash tylko do projektu, który jest częścią tego, więc nawet jeśli zshjakaś inna potężna powłoka może go obejść, nie będzie to dla mnie realnym rozwiązaniem.

Jak mogę uzyskać czas potrzebny na uruchomienie zestawu potoków? A skoro już to robimy, dlaczego to nie działa? Wygląda na to, że timenatychmiast kończy działanie, gdy tylko zakończy się pierwsze polecenie. Czemu?

Wiem, że mogę uzyskać indywidualne czasy za pomocą czegoś takiego:

( time foo.sh ) 2>foo.time | ( time bar.sh ) 2> bar.time

Ale nadal chciałbym wiedzieć, czy jest możliwe, aby całość czasu zaplanować jako pojedynczą operację.

¹ _{To nie wydaje się być problemem z buforem, próbowałem uruchomić skrypty z, unbuffereda stdbuf -i0 -o0 -e0liczby były nadal drukowane przed timewyjściem.}

To jest praca.

Różne części potoku są wykonywane jednocześnie. Jedyną rzeczą, która synchronizuje / szereguje procesy w potoku jest IO, tj. Jeden proces zapisujący do następnego procesu w potoku i następny proces czytający to, co pisze pierwszy. Oprócz tego wykonują się niezależnie od siebie.

Ponieważ między procesami w potoku nie ma odczytu ani zapisu, czas jego wykonania jest najdłuższy sleep.

Równie dobrze mógłbyś napisać

time ( foo.sh & bar.sh &; wait )

Terdon opublikował kilka nieznacznie zmodyfikowanych przykładowych skryptów na czacie :

#!/bin/sh
# This is "foo.sh"
echo 1; sleep 1
echo 2; sleep 1
echo 3; sleep 1
echo 4

i

#!/bin/sh
# This is "bar.sh"
sleep 2
while read line; do
  echo "LL $line"
done
sleep 1

Zapytanie brzmiało: „dlaczego time ( sh foo.sh | sh bar.sh )zwraca 4 sekundy zamiast 3 + 3 = 6 sekund?”

Aby zobaczyć, co się dzieje, w tym przybliżony czas wykonania każdego polecenia, można to zrobić (wynik zawiera moje adnotacje):

$ time ( env PS4='$SECONDS foo: ' sh -x foo.sh | PS4='$SECONDS bar: ' sh -x bar.sh )
0 bar: sleep 2
0 foo: echo 1     ; The output is buffered
0 foo: sleep 1
1 foo: echo 2     ; The output is buffered
1 foo: sleep 1
2 bar: read line  ; "bar" wakes up and reads the two first echoes
2 bar: echo LL 1
LL 1
2 bar: read line
2 bar: echo LL 2
LL 2
2 bar: read line  ; "bar" waits for more
2 foo: echo 3     ; "foo" wakes up from its second sleep
2 bar: echo LL 3
LL 3
2 bar: read line
2 foo: sleep 1
3 foo: echo 4     ; "foo" does the last echo and exits
3 bar: echo LL 4
LL 4
3 bar: read line  ; "bar" fails to read more
3 bar: sleep 1    ; ... and goes to sleep for one second

real    0m4.14s
user    0m0.00s
sys     0m0.10s

Tak więc, aby stwierdzić, rurociąg trwa 4 sekundy, a nie 6, ze względu na buforowanie wyjścia z dwóch pierwszych połączeń do echow foo.sh.

Czy byłby to lepszy przykład?

$ time perl -e 'alarm(3); 1 while 1;' | perl -e 'alarm(4); 1 while 1;'
Alarm clock

real    0m4.004s
user    0m6.992s
sys     0m0.004s

Skrypty busyloop trwają 3 i 4 sekundy (odpowiednio), zajmując łącznie 4 sekundy w czasie rzeczywistym z powodu równoległego wykonywania i 7 sekund czasu procesora. (przynajmniej w przybliżeniu.)

Albo to:

$ time ( sleep 2; echo) | ( read x; sleep 3 )

real    0m5.004s
user    0m0.000s
sys     0m0.000s

Nie działają one równolegle, więc całkowity czas to 5 sekund. Wszystko to spędza się na spaniu, więc nie potrzeba czasu procesora.

Jeśli masz sysdig, możesz wstawiać znaczniki w dowolnych punktach, zakładając, że możesz zmodyfikować kod, aby dodać niezbędne zapisy/dev/null

echo '>::blah::' >/dev/null
foo.sh | bar.sh
echo '<::blah::' >/dev/null

(ale to nie spełnia wymogu „pojedynczej operacji”), a następnie rejestruje rzeczy za pośrednictwem

$ sudo sysdig -w blalog "span.tags contains blah"

i wtedy prawdopodobnie będziesz potrzebował dłuta sysdig, aby wyeksportować tylko czasy

description = "Exports sysdig span tag durations";
short_description = "Export span tag durations.";
category = "Tracers";

args = {}

function on_init()
    ftags = chisel.request_field("span.tags")
    flatency = chisel.request_field("span.duration")
    chisel.set_filter("evt.type=tracer and evt.dir=<")
    return true
end

function on_event()
    local tags = evt.field(ftags)
    local latency = evt.field(flatency)
    if latency then
        print(tostring(tags) .. "\t" .. tonumber(latency) / 1e9)
    end
    return true
end

które kiedyś zapisano w sysdig/chiselskatalogu jako plik spantagduration.lua może być użyty jako

$ sysdig -r blalog -c spantagduration
...

Możesz też pobawić się csysdigwyjściem JSON lub.