Dlaczego iteracja po pliku jest dwa razy szybsza niż wczytywanie go do pamięci i przetwarzanie dwukrotnie?

Porównuję następujące

tail -n 1000000 stdout.log | grep -c '"success": true'
tail -n 1000000 stdout.log | grep -c '"success": false'

z następującymi

log=$(tail -n 1000000 stdout.log)
echo "$log" | grep -c '"success": true'
echo "$log" | grep -c '"success": false'

i zaskakująco drugi zajmuje prawie 3 razy dłużej niż pierwszy. Powinno być szybciej, prawda?

Z jednej strony pierwsza metoda wywołuje taildwa razy, więc musi wykonać więcej pracy niż druga metoda, która robi to tylko raz. Z drugiej strony, druga metoda musi skopiować dane do powłoki, a następnie wycofać, więc musi wykonać więcej pracy niż pierwsza wersja, do której tailjest bezpośrednio podłączona grep. Pierwszy sposób ma dodatkową korzyść w maszynie wieloprocesorowym: grepmoże pracować równolegle tail, przy czym drugi sposób jest ściśle odcinkach, po pierwsze tail, po czym grep.

Nie ma więc oczywistego powodu, dla którego jeden powinien być szybszy od drugiego.

Jeśli chcesz zobaczyć, co się dzieje, sprawdź, jakie wywołania systemowe wykonuje powłoka. Spróbuj także z różnymi powłokami.

strace -t -f -o 1.strace sh -c '
  tail -n 1000000 stdout.log | grep "\"success\": true" | wc -l;
  tail -n 1000000 stdout.log | grep "\"success\": false" | wc -l'

strace -t -f -o 2-bash.strace bash -c '
  log=$(tail -n 1000000 stdout.log);
  echo "$log" | grep "\"success\": true" | wc -l;
  echo "$log" | grep "\"success\": true" | wc -l'

strace -t -f -o 2-zsh.strace zsh -c '
  log=$(tail -n 1000000 stdout.log);
  echo "$log" | grep "\"success\": true" | wc -l;
  echo "$log" | grep "\"success\": true" | wc -l'

W metodzie 1 głównymi etapami są:

1. tail czyta i szuka punktu wyjścia.
2. tailzapisuje fragmenty o długości 4096 bajtów, które grepodczytują tak szybko, jak są tworzone.
3. Powtórz poprzedni krok dla drugiego ciągu wyszukiwania.

W metodzie 2 główne etapy to:

1. tail czyta i szuka punktu wyjścia.
2. tail zapisuje fragmenty o długości 4096 bajtów, które bash odczytuje jednocześnie 128 bajtów, a zsh odczytuje jednocześnie 4096 bajtów.
3. Bash lub zsh zapisuje fragmenty o wielkości 4096 bajtów, które grepodczytują tak szybko, jak są tworzone.
4. Powtórz poprzedni krok dla drugiego ciągu wyszukiwania.

128-bajtowe fragmenty Basha podczas czytania wyniku podstawienia polecenia znacznie go spowalniają; Zsh wychodzi dla mnie tak szybko jak metoda 1. Twój przebieg może się różnić w zależności od rodzaju i liczby procesorów, konfiguracji harmonogramu, wersji zaangażowanych narzędzi i wielkości danych.

Zrobiłem następujący test i w moim systemie wynikowa różnica jest około 100 razy dłuższa dla drugiego skryptu.

Mój plik jest wyjściem strace o nazwie bigfile

$ wc -l bigfile.log 
1617000 bigfile.log

Skrypty

xtian@clafujiu:~/tmp$ cat p1.sh
tail -n 1000000 bigfile.log | grep '"success": true' | wc -l
tail -n 1000000 bigfile.log | grep '"success": false' | wc -l

xtian@clafujiu:~/tmp$ cat p2.sh
log=$(tail -n 1000000 bigfile.log)
echo "$log" | grep '"success": true' | wc -l
echo "$log" | grep '"success": true' | wc -l

Właściwie nie mam żadnych dopasowań dla grep, więc nic nie jest zapisywane do ostatniego potoku do wc -l

Oto czasy:

xtian@clafujiu:~/tmp$ time bash p1.sh
0
0

real    0m0.381s
user    0m0.248s
sys 0m0.280s
xtian@clafujiu:~/tmp$ time bash p2.sh
0
0

real    0m46.060s
user    0m43.903s
sys 0m2.176s

Uruchomiłem więc dwa skrypty ponownie za pomocą polecenia strace

strace -cfo p1.strace bash p1.sh
strace -cfo p2.strace bash p2.sh

Oto wyniki ze śladów:

$ cat p1.strace 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.24    0.508109       63514         8         2 waitpid
  1.61    0.008388           0     84569           read
  1.08    0.005659           0     42448           write
  0.06    0.000328           0     21233           _llseek
  0.00    0.000024           0       204       146 stat64
  0.00    0.000017           0       137           fstat64
  0.00    0.000000           0       283       149 open
  0.00    0.000000           0       180         8 close
...
  0.00    0.000000           0       162           mmap2
  0.00    0.000000           0        29           getuid32
  0.00    0.000000           0        29           getgid32
  0.00    0.000000           0        29           geteuid32
  0.00    0.000000           0        29           getegid32
  0.00    0.000000           0         3         1 fcntl64
  0.00    0.000000           0         7           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    0.522525                149618       332 total

I p2.strace

$ cat p2.strace 
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 75.27    1.336886      133689        10         3 waitpid
 13.36    0.237266          11     21231           write
  4.65    0.082527        1115        74           brk
  2.48    0.044000        7333         6           execve
  2.31    0.040998        5857         7           clone
  1.91    0.033965           0    705681           read
  0.02    0.000376           0     10619           _llseek
  0.00    0.000000           0       248       132 open
...
  0.00    0.000000           0       141           mmap2
  0.00    0.000000           0       176       126 stat64
  0.00    0.000000           0       118           fstat64
  0.00    0.000000           0        25           getuid32
  0.00    0.000000           0        25           getgid32
  0.00    0.000000           0        25           geteuid32
  0.00    0.000000           0        25           getegid32
  0.00    0.000000           0         3         1 fcntl64
  0.00    0.000000           0         6           set_thread_area
------ ----------- ----------- --------- --------- ----------------
100.00    1.776018                738827       293 total

Analiza

Nic dziwnego, że w obu przypadkach większość czasu spędza się na oczekiwaniu na zakończenie procesu, ale p2 czeka 2,63 razy dłużej niż p1, a jak wspomnieli inni, zaczynasz późno w p2.sh.

Więc teraz zapomnij o waitpid, zignoruj %kolumnę i spójrz na kolumnę sekund na obu śladach.

Największy czas p1 spędza większość czasu na czytaniu prawdopodobnie zrozumiale, ponieważ jest duży plik do odczytu, ale p2 spędza 28,82 razy dłużej w czytaniu niż p1. - bashnie spodziewa się odczytać tak dużego pliku do zmiennej i prawdopodobnie odczytuje bufor jednocześnie, dzieląc go na linie, a następnie otrzymując inny.

liczba odczytów p2 wynosi 705k vs 84k dla p1, każdy odczyt wymaga przełączenia kontekstu w przestrzeń jądra i ponownie. Prawie 10-krotna liczba odczytów i przełączników kontekstu.

Czas zapisu p2 spędza 41,93 razy dłużej na zapisie niż p1

liczba zapisów p1 robi więcej zapisów niż p2, 42k vs 21k, jednak są one znacznie szybsze.

Prawdopodobnie z powodu echolinii do grepw przeciwieństwie do buforów zapisu ogona.

Co więcej , p2 spędza więcej czasu na pisaniu niż na czytaniu, p1 jest na odwrót!

Inny czynnik Spójrz na liczbę brkwywołań systemowych: p2 wydaje 2,42 razy dłużej na łamanie niż na czytanie! W p1 (nawet się nie rejestruje). brkdzieje się, gdy program musi rozszerzyć przestrzeń adresową, ponieważ początkowo nie przydzielono wystarczającej ilości miejsca, prawdopodobnie wynika to z bashu konieczności odczytu tego pliku do zmiennej i nie spodziewania się, że będzie on tak duży, i jak wspomniał @scai, jeśli plik staje się zbyt duży, nawet to nie działałoby.

tailjest prawdopodobnie dość wydajnym czytnikiem plików, ponieważ właśnie do tego został przeznaczony, prawdopodobnie mapuje plik i skanuje pod kątem przerwania linii, umożliwiając w ten sposób jądrze zoptymalizowanie operacji wejścia / wyjścia. bash nie jest tak dobry na czas spędzony na czytaniu i pisaniu.

p2 spędza 44 ms i 41 ms clonei execvnie jest to wymierna ilość dla p1. Prawdopodobnie bash czyta i tworzy zmienną z ogona.

Wreszcie Totals p1 wykonuje ~ 150 tys. Wywołań systemowych w porównaniu z p2 740 tys. (4,93 razy więcej).

Eliminując oczekiwanie, p1 spędza 0,014416 sekund na wykonywaniu wywołań systemowych, p2 0,439132 sekund (30 razy dłużej).

Wygląda więc na to, że p2 spędza większość czasu w przestrzeni użytkownika, nie robiąc nic poza czekaniem na zakończenie wywołań systemowych i zreorganizowaniem pamięci przez jądro, p1 wykonuje więcej zapisów, ale jest bardziej wydajny i powoduje znacznie mniejsze obciążenie systemu, a zatem jest szybszy.

Wniosek

Nigdy nie próbowałbym się martwić kodowaniem przez pamięć podczas pisania skryptu bash, co nie znaczy, że nie próbujesz być wydajny.

tailjest zaprojektowany do robienia tego, co robi, prawdopodobnie jest memory mapsto plik, dzięki czemu jest efektywny w czytaniu i pozwala jądru zoptymalizować operacje we / wy.

Lepszym sposobem na zoptymalizowanie problemu może być najpierw grep„sukces”: „linie”, a następnie liczyć trues i falses, grepma opcję zliczania, która ponownie pozwala uniknąć wc -l, a nawet lepiej, przepuszczać ogon awki liczyć true i załamuje się jednocześnie. p2 nie tylko długo trwa, ale dodaje obciążenie do systemu, gdy pamięć jest tasowana przy pomocy brk.

Właściwie pierwsze rozwiązanie również odczytuje plik do pamięci! Nazywa się to buforowaniem i jest automatycznie wykonywane przez system operacyjny.

I jak już poprawnie wyjaśniono przez mikeserv, pierwsze rozwiązanie sprawdza się grep podczas odczytywania pliku, podczas gdy drugie rozwiązanie wykonuje go po odczytaniu pliku tail.

Pierwsze rozwiązanie jest szybsze z powodu różnych optymalizacji. Ale nie zawsze musi to być prawda. W przypadku naprawdę dużych plików, których system operacyjny postanawia nie buforować, drugie rozwiązanie może stać się szybsze. Pamiętaj jednak, że w przypadku jeszcze większych plików, które nie zmieszczą się w pamięci, drugie rozwiązanie w ogóle nie będzie działać.

Myślę, że główna różnica polega po prostu na echopowolności. Rozważ to:

$ time (tail -n 1000000 foo | grep 'true' | wc -l; 
        tail -n 1000000 foo | grep 'false' | wc -l;)
666666
333333

real    0m0.999s
user    0m1.056s
sys     0m0.136s

$ time (log=$(tail -n 1000000 foo); echo "$log" | grep 'true' | wc -l; 
                                    echo "$log" | grep 'false' | wc -l)
666666
333333

real    0m4.132s
user    0m3.876s
sys     0m0.468s

$ time (tail -n 1000000 foo > bb;  grep 'true' bb | wc -l; 
                                   grep 'false' bb | wc -l)
666666
333333

real    0m0.568s
user    0m0.512s
sys     0m0.092s

Jak widać powyżej, czasochłonnym krokiem jest wydruk danych. Jeśli po prostu przekierujesz do nowego pliku i przejrzysz go, jest to o wiele szybsze, gdy czytasz plik tylko raz.

I zgodnie z prośbą, z ciągiem tutaj:

 $ time (log=$(tail -n 1000000 foo); grep 'true' <<< $log | wc -l; 
                                     grep 'false' <<< $log | wc -l  )
1
1

real    0m7.574s
user    0m7.092s
sys     0m0.516s

Ten jest nawet wolniejszy, prawdopodobnie dlatego, że ciąg tutaj łączy wszystkie dane w jedną długą linię, co spowolni grep:

$ tail -n 1000000 foo | (time grep -c 'true')
666666

real    0m0.500s
user    0m0.472s
sys     0m0.000s

$ tail -n 1000000 foo | perl -pe 's/\n/ /' | (time grep -c 'true')
1

real    0m1.053s
user    0m0.048s
sys     0m0.068s

Jeśli zmienna jest cytowana, aby nie nastąpiło dzielenie, rzeczy są nieco szybsze:

 $ time (log=$(tail -n 1000000 foo); grep 'true' <<< "$log" | wc -l; 
                                     grep 'false' <<< "$log" | wc -l  )
666666
333333

real    0m6.545s
user    0m6.060s
sys     0m0.548s

Ale wciąż powolny, ponieważ krokiem ograniczającym szybkość jest drukowanie danych.

Próbowałem też tego ... Najpierw zbudowałem plik:

printf '"success": "true"
        "success": "true"
        "success": "false"
        %.0b' `seq 1 500000` >|/tmp/log

Jeśli sam wykonasz powyższe, powinieneś wymyślić 1,5 miliona linii /tmp/logze stosunkiem "success": "true"linii 2: 1 do "success": "false"linii.

Następną rzeczą, którą zrobiłem, było przeprowadzenie testów. Wszystkie testy przeprowadziłem przez serwer proxy, shwięc timemusiałbym tylko obserwować jeden proces - i dlatego mogłem pokazać jeden wynik dla całego zadania.

Wydaje się to być najszybsze, mimo że dodaje drugi deskryptor pliku i tee,myślę, że potrafię wyjaśnić, dlaczego:

    time sh <<-\CMD
        . <<HD /dev/stdin | grep '"success": "true"' | wc -l
            tail -n 1000000 /tmp/log | { tee /dev/fd/3 |\
                grep '"success": "false"' |\
                    wc -l 1>&2 & } 3>&1 &
        HD
    CMD
666666
333334
sh <<<''  0.11s user 0.08s system 84% cpu 0.224 total

Oto twój pierwszy:

    time sh <<\CMD
        tail -n 1000000 /tmp/log | grep '"success": "true"' | wc -l
        tail -n 1000000 /tmp/log | grep '"success": "false"' | wc -l
    CMD

666666
333334
sh <<<''  0.31s user 0.17s system 148% cpu 0.323 total

A twój drugi:

    time sh <<\CMD
        log=$(tail -n 1000000 /tmp/log)
        echo "$log" | grep '"success": "true"' | wc -l
        echo "$log" | grep '"success": "false"' | wc -l
    CMD
666666
333334
sh <<<''  2.12s user 0.46s system 108% cpu 2.381 total

Widać, że w moich testach było więcej niż 3 * różnica prędkości podczas wczytywania go do zmiennej, tak jak ty.

Myślę, że część tego polega na tym, że zmienna powłoki musi być dzielona i obsługiwana przez powłokę podczas odczytu - nie jest to plik.

Z here-documentdrugiej strony, dla wszystkich celów i celów, jest file- ifile descriptor, tak. I jak wszyscy wiemy - Unix działa z plikami.

Najbardziej interesujące jest dla mnie here-docsto, że możesz nimi manipulować file-descriptors- prosto |pipe- i wykonywać je. Jest to bardzo przydatne, ponieważ pozwala ci nieco więcej swobodnie wskazywać, |pipegdzie chcesz.

Musiałem ponieważ pierwsze zjada i nie ma nic do drugiego czytania. Ale odkąd go włączyłem i podniosłem, żeby przejść do niego, nie miało to większego znaczenia. Jeśli korzystasz z tylu innych, polecam:teetailgrephere-doc |pipe|piped/dev/fd/3>&1 stdout,grep -c

    time sh <<-\CMD
        . <<HD /dev/stdin | grep -c '"success": "true"'
            tail -n 1000000 /tmp/log | { tee /dev/fd/3 |\
                grep -c '"success": "false"' 1>&2 & } 3>&1 &
        HD
    CMD
666666
333334
sh <<<''  0.07s user 0.04s system 62% cpu 0.175 total

Jest jeszcze szybszy.

Ale kiedy uruchamiam go bez . sourcingopcji, heredocnie mogę z powodzeniem uruchomić pierwszego procesu, aby uruchomić je w pełni jednocześnie. Oto bez pełnego tła:

    time sh <<\CMD
        tail -n 1000000 /tmp/log | { tee /dev/fd/3 |\
            grep -c '"success": "true"' 1>&2 & } 3>&1 |\
                grep -c '"success": "false"'
    CMD
666666
333334
sh <<<''  0.10s user 0.08s system 109% cpu 0.165 total

Ale kiedy dodam &:

    time sh <<\CMD
        tail -n 1000000 /tmp/log | { tee /dev/fd/3 |\
            grep -c '"success": "true"' 1>&2 & } 3>&1 & |\
                grep -c '"success": "false"'
    CMD
sh: line 2: syntax error near unexpected token `|'

Mimo to różnica wydaje się wynosić zaledwie kilka setnych sekundy, przynajmniej dla mnie, więc weź ją tak, jak chcesz.

W każdym razie powodem, dla którego działa szybciej, teejest to, że oba grepsdziałają w tym samym czasie z jednym wywołaniem tail. teeduplikatu pliku dla nas i dzieli go na drugi grepproces wszystkie w strumieniu - wszystko działa od początku do końca, więc wszystko kończy się w tym samym czasie.

Wracając do pierwszego przykładu:

    tail | grep | wc #wait til finished
    tail | grep | wc #now we're done

A twój drugi:

    var=$( tail ) ; #wait til finished
    echo | grep | wc #wait til finished
    echo | grep | wc #now we're done

Ale kiedy podzielimy nasze dane wejściowe i uruchomimy nasze procesy jednocześnie:

          3>&1  | grep #now we're done
              /        
    tail | tee  #both process together
              \  
          >&1   | grep #now we're done