Моя проблема, кратко
Я внес изменения в свою библиотеку, теперь она намного медленнее, но я не могу понять, где она проводит все это дополнительное время. Профилирование отчетов не помогает. Пожалуйста, помогите мне выяснить причину.
Некоторый контекст
Я создал клиентскую библиотеку Redis под названием Hedis и у меня есть программа для тестирования. Теперь я сделал некоторые внутренние изменения в библиотеке, чтобы очистить архитектуру. Это привело к снижению производительности (в запросах Redis в секунду, измеряемой указанным тестом) примерно в 2,5 раза.
Тест открывает 50 сетевых подключений к серверу Redis на локальном хосте. Соединения обрабатываются по-разному между двумя версиями:
- Быстрая версия использует один поток на соединение (таким образом, в тесте производительности одновременно работает 50 потоков). Он читает из сокета
обрабатывать с помощью
unsafeInterleaveIO (я опишу свой подход в широком
штрихи в сообщении в блоге здесь ). Я была немного несчастна
с архитектурой, следовательно, я изменил вещи на
- медленная версия , которая использует три потока на соединение. Они связываются через два
Chan s (150 потоков, работающих в тесте производительности).
Еще немного информации, которая может иметь отношение к делу:
- Составлено с GHC 7.2.2.
- Программа сравнения не меняется между двумя версиями, поэтому сеть
трафик такой же.
- Обе версии используют однопоточную среду выполнения (скомпилировано без
-threaded).
- Все темы создаются путем вызова
forkIO. не дороже
forkOS.
Результаты профилирования
Профилирование не дает мне четкой причины падения производительности. Согласно отчету о профилировании, обе версии проводят более 99% своего времени в System.IO.hFlush и Data.ByteString.hGetSome. Количество вызовов hFlush и hGetSome одинаково в обеих версиях. Поскольку сетевой трафик в обоих случаях одинаков, эти функции не могут быть причиной замедления.
Единственное существенное различие, которое я могу измерить между двумя версиями, заключается в том, что time (утилита Unix) говорит мне: медленная версия (с трехкратным числом потоков) тратит значительно больше времени на "sys" вместо "user" ", по сравнению с быстрой версией. Флаг GHC +RTS -s сообщает об этом как о сниженной производительности.
Вот выходные данные программы для обеих версий с флагом +RTS -s:
Тест быстрой версии
$ time ./dist/build/hedis-benchmark/hedis-benchmark +RTS -s -p
ping 33305.29 Req/s
get 25802.92 Req/s
mget 18215.94 Req/s
ping (pipelined) 268994.36 Req/s
5,118,163,904 bytes allocated in the heap
185,075,608 bytes copied during GC
4,084,384 bytes maximum residency (39 sample(s))
916,544 bytes maximum slop
10 MB total memory in use (0 MB lost due to fragmentation)
Tot time (elapsed) Avg pause Max pause
Gen 0 7416 colls, 0 par 0.38s 0.40s 0.0001s 0.0003s
Gen 1 39 colls, 0 par 0.03s 0.03s 0.0007s 0.0009s
INIT time 0.00s ( 0.00s elapsed)
MUT time 7.93s ( 12.34s elapsed)
GC time 0.41s ( 0.43s elapsed)
RP time 0.00s ( 0.00s elapsed)
PROF time 0.00s ( 0.00s elapsed)
EXIT time 0.00s ( 0.00s elapsed)
Total time 8.33s ( 12.76s elapsed)
%GC time 4.9% (3.3% elapsed)
Alloc rate 645,587,554 bytes per MUT second
Productivity 95.1% of total user, 62.1% of total elapsed
real 0m12.772s
user 0m8.334s
sys 0m4.424s
Тест медленной версии
$ time ./dist/build/hedis-benchmark/hedis-benchmark +RTS -s -p
ping 11457.83 Req/s
get 11169.64 Req/s
mget 8446.96 Req/s
ping (pipelined) 130114.31 Req/s
6,053,055,680 bytes allocated in the heap
1,184,574,408 bytes copied during GC
9,750,264 bytes maximum residency (198 sample(s))
2,872,280 bytes maximum slop
26 MB total memory in use (0 MB lost due to fragmentation)
Tot time (elapsed) Avg pause Max pause
Gen 0 9105 colls, 0 par 2.11s 2.14s 0.0002s 0.0006s
Gen 1 198 colls, 0 par 0.23s 0.24s 0.0012s 0.0093s
INIT time 0.00s ( 0.00s elapsed)
MUT time 10.99s ( 27.92s elapsed)
GC time 2.34s ( 2.38s elapsed)
RP time 0.00s ( 0.00s elapsed)
PROF time 0.00s ( 0.00s elapsed)
EXIT time 0.00s ( 0.00s elapsed)
Total time 13.33s ( 30.30s elapsed)
%GC time 17.6% (7.8% elapsed)
Alloc rate 550,656,490 bytes per MUT second
Productivity 82.4% of total user, 36.3% of total elapsed
real 0m30.305s
user 0m13.333s
sys 0m16.964s
Есть ли у вас какие-либо идеи или подсказки, откуда могло бы появиться это дополнительное время?