Jak mogę wyliczyć fajkę?


27

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 1 .

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ę.


1 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.


Czy próbowałeś go z fizycznym stoperem?
pericynthion

@pericynthion tak, ostatecznie to zrobiłem. I to również pokazało, co wyjaśniają odpowiedzi: czas faktycznie działa, ale (oczywiście i jak powinienem był zdawać sobie sprawę) polecenia w potoku działają jednocześnie, więc poświęcony czas jest zasadniczo czasem najwolniejszym.
terdon

Odpowiedzi:


33

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.


1
@terdon wartości są sumami, ale skrypty zajmują bardzo mało czasu użytkownika i systemu - po prostu czekają, co się nie liczy (z wyjątkiem czasu zegara ściennego).
Stephen Kitt

2
Zauważ, że niektóre powłoki, takie jak powłoka Bourne'a, lub ksh93tylko czekają na ostatni komponent potoku ( sleep 3 | sleep 1trwałby 1 sekundę). powłoka Bourne'a nie ma timesłowa kluczowego, ale ksh93podczas działania z timewszystkimi komponentami są czekane.
Stéphane Chazelas

3
Mówię tylko, że można się dziwić, że w ksh93 sleep 10 | sleep 1zajmuje to sekundę, a time sleep 10 | sleep 110 sekund. W powłoce Bourne'a zabrałoby time sleep 10 | sleep 1to sekundę, ale otrzymałeś wynik czasu ( sleep 10tylko i od /usr/bin/time) z niebieskiego 9 sekund później.
Stéphane Chazelas,

1
Tu nie chodzi o strzeżenie czegokolwiek. timepoprawnie razy potokuje potok, ale zmienia zachowanie powłoki w ksh93. (sleep 10 | sleep 1)zajmuje 1 sekundę, time (sleep 10 | sleep 1)zajmuje 10 sekund. { (sleep 10 | sleep 1); echo x; }wyjścia xpo 1 sekundzie, time { (sleep 10 | sleep 1); echo x; }wyjścia xpo 10 sek. To samo, jeśli umieścisz ten kod w funkcji i czas funkcji.
Stéphane Chazelas,

1
Zauważ, że ksh93jak w zsh( -o promptsubsttutaj), możesz zrobić, typeset -F SECONDSaby uzyskać mniej przybliżoną liczbę sekund (POSIXsh nie ma SECONDS)
Stéphane Chazelas

10

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.


3

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.

Korzystając z naszej strony potwierdzasz, że przeczytałeś(-aś) i rozumiesz nasze zasady używania plików cookie i zasady ochrony prywatności.
Licensed under cc by-sa 3.0 with attribution required.