Профилируем сортировку FreeBSD
Программа сортировки FreeBSD (sort) считывает строки из ввода или файла и возвращает те же строки в отсортированном порядке. У NetBSD есть аналогичная программа, есть такая же и у GNU. Недавно мы получили багрепорт, в котором говорилось, что сортировка FreeBSD намного медленнее, чем сортировка NetBSD или GNU.
Я сгенерировал некоторые тестовые данные и запустил тесты. Я использовал числовую сортировку, поэтому вы видите флаг -n :
time sort -n test.txt -o /dev/null # FreeBSD
39.13 real 38.65 user 0.49 sys
time sort -n test.txt -o /dev/null # NetBSD
3.51 real 2.89 user 0.58 sys
time gsort -n --parallel=1 test.txt -o /dev/null # GNU
6.34 real 5.69 user 0.64 sys
Действительно, она значительно медленнее! Заинтригованный, я сначала взглянул на исходный код sort, но ничего необычного при первичном осмотре не заметил. Это означало, что мне нужно будет использовать инструменты профилирования, чтобы определить корень проблемы.
Так как я тестировал сортировку на больших файлах, мне было интересно, тратит ли программа много времени на выделение памяти, поэтому я решил сначала посмотреть на количество аллокаций, которые делает программа. Это можно сделать, подсчитав количество вызовов malloc и других связанных функций, таких как realloc. Я сделал это с помощью инструмента dtrace.
# dtrace -n 'pid$target::*alloc:entry {@ = count()}' -c "sort -n -o /dev/null test.txt"
Этот вызов dtrace на выходе дал мне общее число всех вызовов malloc, realloc и т. д. Для своего тестового файла из 999999 строк я получил результат в 40019544 вызова. Это четыре аллокации на каждую строку из файла с входными данными! Для справки, сортировка NetBSD и GNU имели менее 100 на тех же входных данных. Поскольку аллокации стоят дорого, мы определенно могли бы добиться значительного ускорения, если бы сразу выделяли некоторый пул памяти, а не каждую строку отдельно. Но была ли решена проблема?
Не совсем. Я в очередной раз прибегнул к своему старому доброму инструменту отладки, скромному оператору print. Я поместил один прямо перед вызовом procfile, функции, в которой происходит большинство аллокаций во время подготовки к сортировке, и один сразу после. К сожалению, теперь я мог отчетливо видеть, что эти четыре миллиона malloc происходили в первые несколько секунд, тогда как вся продолжительность программы составляла около 40 секунд. Уменьшение количества malloc могло бы сократить время примерно на 5 секунд, но основная проблема заключалась не в этом. Я до сих пор понятия не имел, какие функции в программе занимают больше всего времени, и использование dtrace для подсчета вызовов функций больше не могло мне помочь.
Следующим, что я попробовал, был инструмент Callgrind в Valgrind. Этот инструмент профилирования записывает количество выполненных инструкций, отсортированных в соответствии с тем, в какой функции они встречаются. Если мы предположим, что каждая инструкция занимает одинаковое количество времени, функция с наибольшим количеством выполненных инструкций также является функцией, которая тратит больше всего времени на выполнение.. Хотя это далеко от истины, но это все-равно достаточно хорошая оценка.
Callgrind можно запустить следующим образом:
$ valgrind --tool=callgrind sort -n -o /dev/null test.txt
Это сгенерирует файл с именем callgrind.out.PID. Callgrind также имеет инструмент callgrind_annotate для удобного отображения содержимого этого файла.
$ callgrind_annotate callgrind.out.PID
Я получил следующий результат:
81,626,980,838 (25.33%) ???:__tls_get_addr [/libexec/ld-elf.so.1] 59,017,375,040 (18.31%) ???:___mb_cur_max [/lib/libc.so.7] 36,767,692,280 (11.41%) ???:read_number [/usr/home/c/Repo/freebsd-src/usr.bin/sort/sort]
Это означает, что около 25% всех инструкций, выполняем в рамках работы программы, приходилось на вызовы функции __tls_get_addr, оставшиеся 18% приходились на ___mb_cur_max и, наконец, 11% приходились на read_number. Обратите внимание, что эти подсчеты являются исключающими; например, если read_number вызывает ___mb_cur_max, инструкции в ___mb_cur_max не будут добавлены к инструкциям в read_number.
Только что это за функции? Две наиболее часто используемые функции, __tld_get_addr и ___mb_cur_max, нигде в исходном коде не встречаются. Оказывается, эти две функции вызываются, когда используется значение MB_CUR_MAX. Хотя это значение выглядит как константа времени компиляции, это не так.
Теперь я начал кое-что понимать, но мне хотелось копнуть глубже. Какие функции использовали MB_CUR_MAX так часто, и зачем? Callgrind не мог дать мне информацию о том, какие конкретно функции привели к этим вызовам __tls_get_addr и ___mb_cur_max.
Тут в дело вступает стектрейс. В каждый конкретный момент времени стектрейс содержит историю того, как программа дошла до этой точки. Если мы будем периодически сохранять стек, то сможем получить представление о том, сколько времени программа тратит на каждую функцию и где она вызывается. Инструмент dtrace, опять же, позволяет нам это сделать.
# dtrace -n 'profile-997 /pid == $target/{@[ustack()] = count()}' -c "sort -n -o /dev/null test.txt" -o out.stacks
Данный вызов dtrace будет записывать стектрейс на протяжении работы всей программы с частотой 997 Гц. Наконец, инструмент FlameGraph обеспечивает полезную, интерактивную и очень красивую визуализацию этих данных:
$ ./stackcollapse.pl out.stacks > out.stacks_folded $ ./flamegraph.pl out.stacks_folded > stacks.svg
Вот результирующая SVG (в оригинале статье интерактивная):
Ось X представляет количество инструкций, тогда как ось Y представляет стек. В отличие от Callgrind, эта визуализация не исключающая; все инструкции, которые выполняются во время вызова функции, учитываются для этой функции. Например, мы видим, что procfile занимает около 8% от общего количества инструкций в программе, sort_list_dump занимает около 10%, а sort_list_to_file занимает около 80%. Мы также можем видеть, что три из этих функций выполняются из функции main.
Эта визуализация подтвердила мою предыдущую гипотезу о том, что четыре миллиона malloc, все в procfile, не так сильно замедляют работу программы. Я также заметил на графике очень длинную полоску со знакомым названием: ___mb_cur_max. Эта функция занимала около 30% инструкций программы, а также отвечала за вызовы __tls_get_addr. Ее вызывала функция read_number.
Теперь я видел очень простую, но эффективную оптимизацию этой программы. Я бы кешировал значение MB_CUR_MAX в начале, чтобы при дальнейшем использовании не нужно было вызывать функции ___mb_cur_max и __tls_get_addr. Я внедрил это изменение и заметил значительное улучшение; это почти вдвое сократило время выполнения!
К сожалению, FlameGraph также дал мне понять, что дальнейшие улучшения программы будут не такими простыми. Большая часть оставшегося времени тратится на использование функции сортировки, которая уходит корнями в libc. И большая часть времени, затрачиваемого на функцию сортировки, приходится на list_coll_offset, numcoll_impl и read_number, которые используются в функции сравнения. Дальнейшая оптимизация этой программы будет означать оптимизацию этих функций, что само по себе уже не так просто, как кэширование значения.
Тем не менее, мы получили приличный прирост производительности в результате этого исследования. А за счет использования флагов сортировки для изменения алгоритма сортировки на quicksort или mergesort вместо heapsort, мы получаем производительность, почти такую же хорошую, как сортировка в GNU или NetBSD.