Mystery функция _L_lock_154 при профилировании с дргиМи

Question

При профилировании моего кода, дргиЙ выводят следующее:

Flat profile: 

Each sample counts as 0.01 seconds. 
    % cumulative self    self  total   
time seconds seconds calls ms/call ms/call name  
30.69  10.55 10.55        _L_lock_154 
16.58  16.25  5.70 1126059616  0.00  0.00 double_cmp 
14.25  21.15  4.90 13737  0.36  0.36 bsdi 
10.01  24.59  3.44        memcpy 

(взять 1-ую несколько только линию)

принимая первое место в функцию я делать не признают, и к сожалению, к сожалению.

что это может быть - кто-нибудь знает? так как его захват львиной доли моего времени я бы хотел узнать.

используя микрофоны предложение для DIY профилирования, я вижу эту трассировку стека довольно часто:

Program received signal SIGINT, Interrupt. 
0xb7fff424 in __kernel_vsyscall() 
(gdb) bt 
#0 0xb7fff424 in __kernel_vsyscall() 
#1 0x080ada62 in __write_nocancel() 
#2 0x080859c1 in _IO_new_file_write() 
#3 0x08084b64 in new_do_write() 
#4 0x080861ed in _IO_new_do_write() 
#5 0x080869c5 in _IO_new_file_overflow() 
#6 0x08085f3e in _IO_new_file_xsputn() 
#7 0x080c4d54 in vfprintf() 
#8 0x080b071c in __fprintf_chk() 
#9 0x0805ec36 in fprint_track_hum() 
#10 0x0805efe1 in fprint_hash_tracks() 
#11 0x08049c33 in main (argc=22, argv=0xbfffeac4) at harness.c:537 

хотя я не вижу вызов _L_lock_154, я начинаю думать, что это может быть что-то печать в файл /stdio.h related - блокировка при записи в указатель файла или некоторые такие. Так что я буду пытаться отключить все печати и повторного профиля см, если функция тайна исчезает ..

UPDATE # 1

нет - его еще немного тайны, отключены все выходные данные в файл/стандартный вывод но sinistrous _L_lock_154 все еще занимает 10% моего времени. Может быть что-то делать с чтением из файла, но я не могу запустить мой жгут без какого-либо входа ..

Я очень удивлен Google рисует пустой на это - очень редкий ..

UPDATE # 2

просто побежал дргоЕ в графе вызовов, а не плоский режим - он выплевывает это для _L_lock_154:

granularity: each sample hit covers 4 byte(s) for 0.03% of 36.86 seconds 

index % time self children called  name 
               <spontaneous> 
[1]  49.6 11.82 6.45     _L_lock_154 [1] 
       5.84 0.00 1198163721/1198163721  double_cmp [8] 
       0.52 0.00 125628587/125628587  fptype_cmp [24] 
       0.04 0.00 13096233/13096233  grp_cmp_by_density_descending [52] 
       0.04 0.00 3464916/3464916  pdw_ptr_cmp_by_amp [53] 
       0.01 0.00 73812/73812  pdw_ptr_cmp_by_idx [89] 
       0.00 0.00 71682/9288620  int_cmp [44] 
       0.00 0.00 636314/842100  pri_ptr_cmp_by_second_pdw_idx [123] 
       0.00 0.00 277089/407783  pri_ptr_cmp_by_first_pdw_idx [124] 
       0.00 0.00 76178/76178  window_cmp_by_emitter_id [128] 
       0.00 0.00 10147/10147  pri_ptr_cmp_by_first_pdw_toa [137] 
----------------------------------------------- 

Я уверен, что это пытается сказать мне что-то, но я не уверен, как интерпретировать его ? Все мои функции типа cmp предназначены для использования с qsort из stdlib - если _L_lock_154 является родительским для всех этих вызовов, подразумевает ли он псевдоним для qsort?

Answer 1

OK, gprof Образцы времени процессора, в то время как случайные паузы образцов на настенные часы. Поэтому, когда gprof говорит, что процедура занимает 30% времени, это означает время CPU, которое может быть меньше 1% времени настенных часов. Другими словами, вы связаны с I/O. Поэтому, даже если вы можете сделать это, потребуется 0 раз, вы никогда не увидите разницы. (Вот почему я унижаю «CPU-профилирование» - это приводит к тому, что менее опытные программисты фокусируют свое внимание на вещах, которые не имеют значения.)

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

Чтобы получить сопоставимые результаты с gprof в случайном порядке, вам придется отбросить любые образцы, содержащие __kernel_vsyscall. Таким образом, вам может потребоваться 100 образцов, прежде чем вы найдете тот, который фактически использует время процессора. Это очень много работы, но если вы это сделали, я ожидаю, что вы увидите процедуру блокировки около 30% образцов без ввода-вывода.

Помните, что когда было написано gprof, это были люди, работающие в Калифорнийском университете в Беркли, в академической среде, где разрабатывалась версия unix. У него было встроенное предположение - все I/O было необходимо I/O. В реальном программном обеспечении на уровне пользователя это часто бывает не так. Кроме того, I/O не является не процессорным временем, это всего лишь различных CPU. В чипе контроллера ввода/вывода работает этот диск, порт или что-то еще.