Это вывод strace -T -ttt -ff -x -y -o pid.trace -p 2145
, Трассировка приведена ниже.
1503431273.934716 semop (1204093022, {{0, 1, SEM_UNDO}}, 1) = 0 <0.000004> 1503431273.934737 clock_gettime (CLOCK_REALTIME, {1503431273, 934741536}) = 0 <0.000004> 1503431273.934763 написать (6</home/red/samples/debug/hexa.debug>, "17.08.23 01:17:53 [hexa: 2145" ..., 79) = 79 <0.000016> 1503431273.934960 brk (0) = 0x1adc000 <0.000004> 1503431273.934974 brk (0x1afd000) = 0x1afd000 <0.000006> 1503431273.934994 brk (0) = 0x1afd000 <0.000003> 1503431273.935006 brk (0) = 0x1afd000 <0.000004> 1503431273.935017 brk (0x1afc000) = 0x1afc000 <0.000008> 1503431273.935033 brk (0) = 0x1afc000 <0.000003> 1503431273,935045 brk (0) = 0x1afc000 <0.000004> 1503431273,935057 brk (0) = 0x1afc000 <0.000004> 1503431273.935068 brk (0x1afb000) = 0x1afb000 <0.000005> 1503431273,935080 brk (0) = 0x1afb000 <0.000003> 1503431291.010338 brk (0) = 0x1afb000 <0.000006> 1503431291.010366 brk (0x1b1c000) = 0x1b1c000 <0.000006> 1503431291.010391 brk (0) = 0x1b1c000 <0.000003> 1503431291.010403 brk (0) = 0x1b1c000 <0.000004> 1503431291.010414 brk (0x1b12000) = 0x1b12000 <0.000008> 1503431291.010430 brk (0) = 0x1b12000 <0.000004> 1503431291.010443 brk (0) = 0x1b12000 <0.000004> 1503431291.010455 brk (0) = 0x1b12000 <0.000003> 1503431291.010466 brk (0x1b11000) = 0x1b11000 <0.000004> 1503431291.010478 brk (0) = 0x1b11000 <0.000004> 1503431301.277050 clock_gettime (CLOCK_REALTIME, {1503431301, 277067441}) = 0 <0.000005> 1503431301.277094 написать (6</home/red/samples/debug/hexa.debug>"17.08.23 01:18:21 [гекса: 2145" ..., 91) = 91 <0.000019> 1503431301.277201 clock_gettime (CLOCK_REALTIME, {1503431301, 277216542}) = 0 <0.000005> 1503431301.277234 написать (6</home/red/samples/debug/hexa.debug>"17.08.23 01:18:21 [гекса: 2145" ..., 126) = 126 <0.000018> 1503431301.277296 clock_gettime (CLOCK_REALTIME, {1503431301, 277301142}) = 0 <0.000004> 1503431301.277317 написать (6</home/red/samples/debug/hexa.debug>"17.08.23 01:18:21 [гекса: 2145" ..., 126) = 126 <0.000012> 1503431301.288030 clock_gettime (CLOCK_REALTIME, {1503431301, 288037704}) = 0 <0.000004>
если вы посмотрите на приведенный выше след в два BRK (0) ы (см. 1503431273.935080 и 1503431291.010478) слишком много времени 17 секунд и 10 секунд соответственно (сравнение левого бокового времени). Но время выполнения в правой части просто минимально. Я сделал несколько запусков этой программы, в том же Redhat Linux box (7.2), все прогоны давали одинаковое время (с разницей в микросекундах) в одном и том же месте системного вызова (brk (0)).
В чем может быть проблема? это на уровне программирования или на уровне ОС? У меня нет исходного кода для этого, но я знаю, что это программа на языке c / c ++.
Чтобы ответить на вопрос в заголовке: Нет, brk(0)
не занимает слишком много времени.
Вы можете увидеть это, посмотрев время, указанное для самого системного вызова (<0.000003>
, добавленный -T
опция). Это всего 3 микросекунды.
Значения слева являются (абсолютными) временными метками. Но это просто означает, что процесс выполнил brk
системный вызов на 1503431273.935080 и другой системный вызов на 1503431291.010338. Это не значит, что какой-то один системный вызов занял 17 секунд; это просто означает, что процессу потребовалось 17 секунд, чтобы достичь следующего системного вызова.
Этот процесс мог выполнять много других задач, например выполнять необработанные вычисления (сжигание ЦП) или не планироваться (поскольку система была занята другими программами). Последний вариант, по общему признанию, маловероятен, потому что вы сказали, что это произошло в нескольких запусках программы. Поэтому я думаю, что наиболее вероятное объяснение состоит в том, что код просто тратит много времени на вычисления без необходимости вызова ядра (например, сжатый числовой код в цикле, без выделения памяти).
Других решений пока нет …