Почему итерация по файлу в два раза быстрее, чем чтение в память и вычисления в два раза?

Я сравниваю следующее

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

со следующим

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

и удивительно, что второе занимает почти в 3 раза больше, чем первое. Это должно быть быстрее, не так ли?

С одной стороны, первый метод вызывается tailдважды, поэтому он должен выполнять больше работы, чем второй метод, который делает это только один раз. С другой стороны, второй метод должен копировать данные в оболочку и затем возвращаться обратно, поэтому он должен выполнять больше работы, чем первая версия, tailв которую напрямую передаются данные grep. Первый метод имеет дополнительное преимущество на многопроцессорной машине: он grepможет работать параллельно tail, тогда как второй метод сначала строго сериализуется tail, а затем grep.

Так что нет очевидной причины, почему один должен быть быстрее другого.

Если вы хотите увидеть, что происходит, посмотрите, что система вызывает из оболочки. Попробуйте тоже с разными оболочками.

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'

При использовании способа 1 основными этапами являются:

1. tail читает и стремится найти его отправную точку.
2. tailзаписывает 4096-байтовые чанки, которые grepчитаются так же быстро, как и создаются.
3. Повторите предыдущий шаг для второй строки поиска.

С помощью метода 2 основными этапами являются:

1. tail читает и стремится найти его отправную точку.
2. tail записывает 4096-байтовые чанки, которые bash читает 128 байтов за раз, а zsh читает 4096 байтов за раз.
3. Bash или zsh записывают 4096-байтовые чанки, которые grepчитаются так же быстро, как и создаются.
4. Повторите предыдущий шаг для второй строки поиска.

128-байтовые чанки Bash при чтении вывода команды подстановки значительно замедляют его; zsh выходит так же быстро, как метод 1 для меня. Ваш пробег может варьироваться в зависимости от типа и количества ЦП, конфигурации планировщика, версий используемых инструментов и размера данных.

Я провел следующий тест, и в моей системе результирующая разница для второго сценария примерно в 100 раз больше.

Мой файл является выводом strace, который называется bigfile

$ wc -l bigfile.log 
1617000 bigfile.log

Сценарии

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

На самом деле у меня нет совпадений для grep, поэтому ничего не записывается в последний канал до wc -l

Вот время:

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

Итак, я снова запустил два скрипта с помощью команды strace

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

Вот результаты из следов:

$ 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

И 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

Анализ

Неудивительно, что в обоих случаях большая часть времени тратится на ожидание завершения процесса, но p2 ждет в 2,63 раза дольше, чем p1, и, как уже упоминали другие, вы начинаете поздно в p2.sh.

Так что теперь забудьте о waitpid, игнорируйте %столбец и посмотрите на столбец секунд на обеих трассах.

Самое большое время p1 тратит большую часть своего времени на чтение, вероятно, понятно, потому что есть большой файл для чтения, но p2 тратит в 28,82 раза больше на чтение, чем p1. - bashне ожидает чтения такого большого файла в переменную и, вероятно, одновременно читает буфер, разбивается на строки и затем получает другой.

число считываний p2 составляет 705 тыс. против 84 тыс. для p1, при каждом чтении требуется переключение контекста в пространство ядра и обратно. Почти в 10 раз превышает число операций чтения и переключения контекста.

Время записи p2 тратит в 41,93 раза больше времени записи, чем p1

количество записей p1 делает больше записей, чем p2, 42k против 21k, однако они намного быстрее.

Вероятно, из- echoза строк в grepотличие от хвостовых буферов записи.

Более того , p2 тратит больше времени на запись, чем на чтение, p1 наоборот!

Другой фактор Посмотрите на количество brkсистемных вызовов: p2 тратит в 2,42 раза больше времени, чем на чтение! В p1 (он даже не регистрируется). brkэто когда программе нужно расширить свое адресное пространство, потому что изначально не было выделено достаточно места, это, вероятно, связано с тем, что bash нужно прочитать этот файл в переменную, а не ожидать, что он будет таким большим, и, как упомянул @scai, если файл становится слишком большим, даже это не будет работать.

tailэто, вероятно, довольно эффективный файл-ридер, потому что это то, для чего он предназначен, он, вероятно, запоминает файл и просматривает разрывы строк, что позволяет ядру оптимизировать ввод-вывод. bash не так хорош как по времени, потраченному на чтение и письмо.

p2 тратит 44 мс и 41 мс, cloneи execvэто не измеримая величина для p1. Вероятно, чтение bash и создание переменной из tail.

В итоге Totals p1 выполняет ~ 150 тыс. Системных вызовов против p2 740 тыс. (В 4,93 раза больше).

Устраняя waitpid, p1 тратит 0,014416 секунды на выполнение системных вызовов, p2 0,439132 секунды (в 30 раз дольше).

Похоже, что p2 проводит большую часть времени в пользовательском пространстве, ничего не делая, кроме ожидания завершения системных вызовов и перестройки памяти ядром, p1 выполняет больше операций записи, но более эффективно и вызывает значительно меньшую нагрузку на систему и, следовательно, быстрее.

Вывод

Я никогда не стал бы беспокоиться о кодировании через память при написании сценария bash, это не значит, что вы не пытаетесь работать эффективно.

tailпредназначен для того, чтобы делать то, что он делает, это, вероятно, memory mapsфайл, чтобы его было удобно читать, и он позволяет ядру оптимизировать ввод / вывод.

Лучшим способом оптимизации вашей проблемы может быть сначала grep«строки успеха»: «, а затем подсчитывать истинные и ложные значения», grepесть опция подсчета, которая снова позволяет избежать wc -lили, что еще лучше, направить хвост к подсчету истинных чисел awkи подсчитать их. ложится одновременно p2 не только занимает много времени, но и добавляет нагрузку на систему, пока память перемешивается с brks.

На самом деле первое решение также считывает файл в память! Это называется кэшированием и автоматически выполняется операционной системой.

И, как уже правильно объяснил mikeserv, первое решение работает grep во время чтения файла, тогда как второе решение выполняет его после того, как файл был прочитан tail.

Поэтому первое решение быстрее из-за различных оптимизаций. Но это не всегда должно быть правдой. Для действительно больших файлов, которые ОС решает не кэшировать, второе решение может стать быстрее. Но обратите внимание, что для еще больших файлов, которые не помещаются в вашей памяти, второе решение не будет работать вообще.

Я думаю, что основное отличие очень простое echo- медленное. Учти это:

$ 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

Как вы можете видеть выше, трудоемким шагом является печать данных. Если вы просто перенаправляете на новый файл и просматриваете его, это происходит намного быстрее, когда вы читаете файл только один раз.

И в соответствии с просьбой, здесь строка:

 $ 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

Это еще медленнее, предположительно потому, что строка здесь объединяет все данные в одну длинную строку, что замедляет 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

Если переменная заключена в кавычки, чтобы не происходило разбиение, все происходит немного быстрее:

 $ 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

Но все еще медленно, потому что шаг ограничения скорости печатает данные.

Я тоже попробовал это ... Сначала я собрал файл:

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

Если вы запустите вышеописанное, вы должны получить 1,5 миллиона строк /tmp/logс соотношением "success": "true"строк : 2: 1 "success": "false".

Следующее, что я сделал, - запустил несколько тестов. Я выполнил все тесты через прокси-сервер, shпоэтому мне timeнужно было наблюдать только один процесс - и, следовательно, мог показать один результат для всей работы.

Это кажется самым быстрым, хотя он добавляет второй дескриптор файла и tee,хотя я думаю, что могу объяснить, почему:

    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

Вот твой первый:

    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

И твой второй:

    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

Вы можете видеть, что в моих тестах скорость чтения была более чем в 3 * раза при чтении в переменную, как вы это делали.

Я думаю, что отчасти это то, что переменная оболочки должна быть разделена и обработана оболочкой во время чтения - это не файл.

here-documentС другой стороны, для всех намерений и целей, это file- этоfile descriptor, в любом случае. И как мы все знаем - Unix работает с файлами.

Что самое интересное для меня в here-docsтом, что вы можете манипулировать их file-descriptors- как прямой |pipe- и выполнять их. Это очень удобно, так как дает вам немного больше свободы, указывая, |pipeкуда вы хотите.

Я должен был , потому что первые съедает и там ничего не осталось за секунду для чтения. Но так как я его в и поднял его снова , чтобы перейти к не имело большого значения. Если вы используете так много других, рекомендуем: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

Это даже быстрее.

Но когда я запускаю его без . sourcingв heredocI не может успешно фон первый процесс , чтобы запустить их в полном объеме одновременно. Вот это без полного фона:

    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

Но когда я добавляю &:

    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 `|'

Тем не менее, разница, похоже, составляет всего несколько сотых долей секунды, по крайней мере для меня, поэтому примите это как хотите.

В любом случае, причина, по которой он работает быстрее, teeзаключается в том, что оба grepsзапускаются одновременно с одним вызовом, который tail. teeдублирует для нас файл и разделяет его со вторым grepпроцессом в потоке - все запускается сразу от начала до конца, поэтому они все заканчивают примерно в одно и то же время.

Итак, возвращаясь к вашему первому примеру:

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

И твой второй:

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

Но когда мы разделяем наш ввод и запускаем наши процессы одновременно:

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