LINUX.ORG.RU
Форум — Development  

Странная проблема с производительностью read/write.


0

0 

Привет!

Есть странная проблема с производительностью read/write.
Есть демон, написанный на perl, который принимает подключение
по TCP и выполняет команду shell.
Делает он это тривиальнейшим способом - fork + exec.

Проблема происходит при посылке команды:
bzcat /tmp/big_file.bz2 | egrep "^[0-9]+" > /dev/null

Проблема заключается в том, что данная команда выполняется  
около 50 секунд, тогда как она же просто запущенная из 
консоли выполняется менее 2 секунд!

Я изучал трассу системных вызовов (strace -ffF -tt) и обнаружил, 
что проблема заключается в низкой производительности 
записи/чтения в пайп (создаваемый шелом).
Почти все 50 секунд 1-й процесс усердно читает данные из файла
и пишет на stdout (т.е. реально в пайп), а 2-й процесс с 
тем же усердием читает данные с stdin (т.е. из пайпа) и пишет их
на stdout (т.е. в /dev/null).

Аналогичный strace команды при запуске из консоли показывает 
почти тот же самый набор read/write, но отрабатывает почти в 20
раз быстрее!

Проблема явно системная, т.к. аналогичная команда, посланная тому
же самому демону на 2-х других серверах выполнилась очень
быстро.

Итак конфигурации систем:
1) Проблемная система.
Linux develop 2.6.14-gentoo-r2 #1 SMP PREEMPT Wed Mar 21 18:43:52 MSK 2007 i686 Intel(R) Pentium(R) 4 CPU 2.80GHz GenuineIntel GNU/Linux

2) Система где всё работает быстро 1
Linux demo 2.6.17-gentoo-r7 #2 SMP Tue Feb 13 19:35:29 MSK 2007 i686 Intel(R) Pentium(R) 4 CPU 3.00GHz GenuineIntel GNU/Linux

3) Система где всё работает быстро 2
Linux test_serv 2.6.9-prep #4 SMP Tue Feb 13 14:30:01 MSK 2007 i686 i686 i386 GNU/Linux

У меня уже закончились идеи на этот счет.
Может кто сталкивался с подобными проблемами.

Спасибо!
← Нужен модуль ядра, подмухлёвывающий время для определённого процесса
аварийное завершение в режиме ядра →

А ты оба теста делал одинаково, то есть сразу после перезагрузки? А то есть такое слово "кэш" и если ты запустишь команду два раза подряд - то во второй раз она выполнится почти мгновенно, а вот в первый раз весьма долго бужать будет :-)

no-dashi ★★★★★
()
Ответ на: комментарий от no-dashi 

Это маловероятно.
Я каждый из тестов выполнял раз по 10 подряд.
Т.е. влияние кэша могло ощущаться только на 1-ых запусках.
У меня же абсолютно стабильное повторяемое поведение.

Krivenok_Dmitry ★
() автор топика
Ответ на: комментарий от Krivenok_Dmitry 

Ниже приводится очень интересный кусочек лога strace'а
для процесса bzcat.
3 - это дескриптор файла архива.
В этом кусочке bzcat считывает очередные 8*4096 = 32768 байт
сырых данных и затем идут серии по 8 вызовов write
(пустые строки конечно вставил я для удобства чтения).
...
...
18:41:31.778190 read(3, ";"..., 4096)   = 4096
18:41:31.778326 read(3, "\306"..., 4096) = 4096
18:41:31.779882 read(3, "\333"..., 4096) = 4096
18:41:31.782987 read(3, "\334"..., 4096) = 4096
18:41:31.785756 read(3, "\252"..., 4096) = 4096
18:41:31.787861 read(3, "\356"..., 4096) = 4096
18:41:31.787955 read(3, "\344"..., 4096) = 4096
18:41:31.790376 read(3, "i"..., 4096)   = 4096

18:41:31.806404 write(1, "o"..., 4096)  = 4096
18:41:31.807001 write(1, "t"..., 4096)  = 4096
18:41:31.807409 write(1, ","..., 4096)  = 4096
18:41:31.807497 write(1, "1"..., 4096)  = 4096
18:41:31.807855 write(1, "t"..., 4096)  = 4096
18:41:31.808225 write(1, ","..., 4096)  = 4096
18:41:31.808580 write(1, ","..., 4096)  = 4096
18:41:31.808928 write(1, "3"..., 4096) = 4096

18:41:32.038562 write(1, "A"..., 4096)  = 4096
18:41:32.038663 write(1, "0"..., 4096)  = 4096
18:41:32.038979 write(1, ","..., 4096)  = 4096
18:41:32.039259 write(1, ","..., 4096)  = 4096
18:41:32.039524 write(1, "e"..., 4096)  = 4096
18:41:32.039796 write(1, "3"..., 4096)  = 4096
18:41:32.040069 write(1, "o"..., 4096)  = 4096
18:41:32.040157 write(1, "6"..., 4096) = 4096

18:41:32.284795 write(1, "i"..., 4096)  = 4096
18:41:32.285136 write(1, ","..., 4096)  = 4096
18:41:32.285426 write(1, "2"..., 4096)  = 4096
18:41:32.285693 write(1, ","..., 4096)  = 4096
18:41:32.285779 write(1, ","..., 4096)  = 4096
18:41:32.286051 write(1, "2"..., 4096)  = 4096
18:41:32.286321 write(1, "\n"..., 4096) = 4096
18:41:32.286593 write(1, "8"..., 4096) = 4096
...
...

Крайне интересно то, что между каждой из серий проходит 
определенное время (до десятых!!! долей секунды).

Ввиду того, что за серию из 8 write'ов пишется 
8 * 4096 = 32768 байт данных и затем следующий write 
притормаживает можно предположить, что просто заполняется
буфер пайпа (судя по книге System UNIX Programming размер этого
буфера равен как раз 32768).
Не знаю как проверить системный параметр, отвечающий за размер
этого буфера (вроде это PIPE_SIZE), но судя по результатам 
книге можно верить.

Т.о. получается, что производитель работает быстрее потребителя.
Т.е. egrep тормозит.

Остается вопрос, почему же при запуске из консоли поведение
другое.
Буду копать дальше :)

Krivenok_Dmitry ★
() автор топика
Ответ на: комментарий от Krivenok_Dmitry 

А вот и кусочек трейса egrep'а.
Сначала идет чтение порции из 32768 байт, затем запись
через 8 вызовов write.
Конечно read может вернуть и меньше (напримен 8192), но 
моя статистика показала, что 32768 возвращается в 99%
случаев.

...
...
18:41:32.038091 read(0, "7"..., 32768)  = 32768
18:41:32.047468 write(1, "c"..., 4096)  = 4096
18:41:32.103326 write(1, "t"..., 4096)  = 4096
18:41:32.153301 write(1, "_"..., 4096)  = 4096
18:41:32.192248 write(1, "0"..., 4096)  = 4096
18:41:32.226744 write(1, "6"..., 4096)  = 4096
18:41:32.252142 write(1, "0"..., 4096)  = 4096
18:41:32.270383 write(1, "9"..., 4096)  = 4096
18:41:32.281023 write(1, ","..., 4096)  = 4096

18:41:32.284282 read(0, "1"..., 32768)  = 32768
18:41:32.293903 write(1, "v"..., 4096)  = 4096
18:41:32.347233 write(1, "."..., 4096)  = 4096
18:41:32.397665 write(1, ","..., 4096)  = 4096
18:41:32.438688 write(1, "0"..., 4096)  = 4096
18:41:32.471832 write(1, "8"..., 4096)  = 4096
18:41:32.497487 write(1, "t"..., 4096)  = 4096
18:41:32.515623 write(1, "v"..., 4096)  = 4096
18:41:32.526580 write(1, "1"..., 4096)  = 4096
...
...

Так вот примечательно сколько времени уходит на 8 вызовов 
write!!! Эти самые десятые доли секунды!!!


Для стравнения привожу трейс скрипта, запущенного из консоли:
...
00:15:37.788799 read(0, "."..., 32768) = 32768
00:15:37.789076 write(1, "n"..., 4096)  = 4096
00:15:37.789234 write(1, "1"..., 4096) = 4096
00:15:37.789330 write(1, "7"..., 4096)  = 4096
00:15:37.789432 write(1, "7"..., 4096)  = 4096
00:15:37.789526 write(1, "2"..., 4096)  = 4096
00:15:37.789666 write(1, "0"..., 4096)  = 4096
00:15:37.789762 write(1, "8"..., 4096)  = 4096
00:15:37.789856 write(1, "t"..., 4096)  = 4096
...

Здесь при выполнении всех 8-ми вызовов write мы не вышли
даже на пределы милисекунды!

Krivenok_Dmitry ★
() автор топика
Ответ на: комментарий от Krivenok_Dmitry

Загрузка CPU какая в обоих случаях?

Murr ★★
()
Ответ на: комментарий от Krivenok_Dmitry

>Так вот примечательно сколько времени уходит на 8 вызовов write!!!

по вашему логу невозможно сделать вывод, сколько времени ушло на вызов. для этого существует ключ -T у strace.

Murr ★★
()
Ответ на: комментарий от Murr 

Согласен.
Однако других вызовов не было.
Т.о. либо write тормозит, либо тормоз в user space.

Важно не это, а разница в поведении в двух случаях.

Krivenok_Dmitry ★
() автор топика

>bzcat /tmp/big_file.bz2 | egrep "^[0-9]+" > /dev/null

bzegrep "^[0-9]+" /tmp/big_file.bz2 >/dev/null

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

php-coder ★★★★★
()
Ответ на: комментарий от Krivenok_Dmitry 

Попробовал с опцией -T.

09:08:37.462280 read(0, "o"..., 32768)  = 32768 <0.000038>
09:08:37.471717 write(1, ","..., 4096)  = 4096 <0.000276>
09:08:37.530214 write(1, "c"..., 4096)  = 4096 <0.000016>
09:08:37.582784 write(1, "t"..., 4096)  = 4096 <0.000016>
09:08:37.624684 write(1, "c"..., 4096)  = 4096 <0.000016>
09:08:37.657868 write(1, "1"..., 4096)  = 4096 <0.000015>
09:08:37.684659 write(1, "1"..., 4096)  = 4096 <0.000016>
09:08:37.705166 write(1, "r"..., 4096)  = 4096 <0.000016>
09:08:37.716202 write(1, ","..., 4096)  = 4096 <0.000016>

09:08:37.719593 read(0, "8"..., 32768)  = 32768 <0.000035>
09:08:37.729274 write(1, "0"..., 4096)  = 4096 <0.000016>
09:08:37.789556 write(1, "4"..., 4096)  = 4096 <0.000016>
09:08:37.841149 write(1, "0"..., 4096)  = 4096 <0.000017>
09:08:37.883498 write(1, ","..., 4096)  = 4096 <0.000017>
09:08:37.919193 write(1, "_"..., 4096)  = 4096 <0.000016>
09:08:37.946793 write(1, ","..., 4096)  = 4096 <0.000016>
09:08:37.966122 write(1, "_"..., 4096)  = 4096 <0.000016>
09:08:37.977541 write(1, "9"..., 4096)  = 4096 <0.000016>

09:08:37.980594 read(0, "r"..., 32768)  = 32768 <0.000040>
09:08:37.990388 write(1, "h"..., 4096)  = 4096 <0.000016>
09:08:38.053253 write(1, "7"..., 4096)  = 4096 <0.000017>
09:08:38.113867 write(1, "0"..., 4096)  = 4096 <0.000018>
09:08:38.157138 write(1, "n"..., 4096)  = 4096 <0.000015>
09:08:38.191478 write(1, "1"..., 4096)  = 4096 <0.000015>
09:08:38.220223 write(1, ","..., 4096)  = 4096 <0.000015>
09:08:38.238937 write(1, "4"..., 4096)  = 4096 <0.000014>
09:08:38.250461 write(1, "7"..., 4096)  = 4096 <0.000015>

Время вполне нормальное.
Однако время между вызовами!? На что оно тратится?

Krivenok_Dmitry ★
() автор топика
Ответ на: комментарий от php-coder 

> Так чуток оптимальнее, потому что не надо будет создавать пайп..

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

Krivenok_Dmitry ★
() автор топика

Чего-то я не нашел в тексте, как эта команда запускается...

Может быть, на серверах просто шеллы разные?

Например, при логине (в консоли) запускается /bin/bash, а демон исполняет через /bin/sh, который может быть линком на что-нмбудь кривое.

anonymous
()
Ответ на: комментарий от Krivenok_Dmitry 

Проблема решена.
Все видно из следующего фрагмента:

develop ~ # locale
LANG=ru_RU.UTF-8
LC_CTYPE="ru_RU.UTF-8"
LC_NUMERIC=POSIX
LC_TIME="ru_RU.UTF-8"
LC_COLLATE="ru_RU.UTF-8"
LC_MONETARY="ru_RU.UTF-8"
LC_MESSAGES=POSIX
LC_PAPER="ru_RU.UTF-8"
LC_NAME="ru_RU.UTF-8"
LC_ADDRESS="ru_RU.UTF-8"
LC_TELEPHONE="ru_RU.UTF-8"
LC_MEASUREMENT="ru_RU.UTF-8"
LC_IDENTIFICATION="ru_RU.UTF-8"
LC_ALL=
develop ~ # time bzcat /tmp/big_file.bz2 | egrep "[0-9]" > /dev/null

real    2m16.893s
user    2m17.353s
sys     0m0.088s
develop ~ # export LANG=POSIX
develop ~ # export LC_ALL=POSIX
develop ~ # locale
LANG=POSIX
LC_CTYPE="POSIX"
LC_NUMERIC="POSIX"
LC_TIME="POSIX"
LC_COLLATE="POSIX"
LC_MONETARY="POSIX"
LC_MESSAGES="POSIX"
LC_PAPER="POSIX"
LC_NAME="POSIX"
LC_ADDRESS="POSIX"
LC_TELEPHONE="POSIX"
LC_MEASUREMENT="POSIX"
LC_IDENTIFICATION="POSIX"
LC_ALL=POSIX
develop ~ # time bzcat /tmp/big_file.bz2 | egrep "[0-9]" > /dev/null

real    0m1.029s
user    0m1.112s
sys     0m0.052s
develop ~ # 

Короче если смотреть уже ltrace'ом, то видно, что egrep вызывает
функцию mbrtowc очень много раз подряд.
Пример вывода ltrace'а:

28779 11:35:32.844621 mbrtowc(0x8099ff0, 0x8073ad8, 9370, 0x80696b8, 58)     = 1 <0.000048>
28779 11:35:32.844764 mbrtowc(0x8099ff4, 0x8073ad9, 9369, 0x80696b8, 58)     = 1 <0.000044>
28779 11:35:32.844881 mbrtowc(0x8099ff8, 0x8073ada, 9368, 0x80696b8, 58)     = 1 <0.000042>
28779 11:35:32.844996 mbrtowc(0x8099ffc, 0x8073adb, 9367, 0x80696b8, 58)     = 1 <0.000045>
28779 11:35:32.845112 mbrtowc(0x809a000, 0x8073adc, 9366, 0x80696b8, 58)     = 1 <0.000044>

Man говорит:
The mbrtowc() function returns the number of bytes parsed from the multibyte sequence.
Судя по тому, что возвращается 1 всё очень плохо.

Krivenok_Dmitry ★
() автор топика
Ответ на: комментарий от Krivenok_Dmitry

Браво! Респект за дотошность. Как в старые добрые времена!...

Sectoid ★★★★★
()
Вы не можете добавлять комментарии в эту тему. Тема перемещена в архив.
← Нужен модуль ядра, подмухлёвывающий время для определённого процесса
Development
аварийное завершение в режиме ядра →