You are viewing poige

Recently I've noticed some really insane values in sys part of timing

« previous entry | next entry »
Dec. 15th, 2011 | 11:56 pm

real    108m1.284s
user    108m51.617s
sys     307445734m57.875s
This is pretty strange as well:
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P COMMAND
27091 poige      1   0  306m  12m 4196 S    0  0.2  5124095h 2 pgadmin3
— WTF?

UPD.: 3.0.13-ck1, up 7:07
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P   TIME COMMAND
25326 poige      1   0  220m  15m  10m S    0  0.2  5124095h 2 30500w leafpad
   13 root       1   0     0    0    0 S    0  0.0  5124095h 2 30500w [ksoftirqd/2]
According to akovalenko's observation, this issue can be related to BFS, so gonna try 3.1.5 w/o it…

UPD. #2: Almost certainly this is a BFS' bug — 3.1.5 w/o BFS is now up for 2:38 now and it stills got no timing screw.

Link | Leave a comment | Share

Comments {17}

Anton Kovalenko

(no subject)

from: akovalenko
date: Dec. 15th, 2011 07:19 pm (UTC)
Link

Это 3.1.*, да? Я тоже страдаю (sbcl/x86-64 от такого ru_stime совсем крышу сносит). Поделитесь, если найдёте решение.

Если оставить в affinity mask единственный CPU, можно этот эффект убрать [для конкретного процесса и его потомков].

Reply | Thread

Igor M Podlesny

> Это 3.1.*, да?

from: poige
date: Dec. 16th, 2011 11:32 am (UTC)
Link

Ага.

> sbcl/x86-64 от такого ru_stime совсем крышу сносит

Мда уж. Тоже неприятно — ХЗ как и на какой софт повлиять может.

Особенно хреново, что трабл реально сложно гуглить — ключевые слова весьма абстрактны. ;-/

Reply | Parent | Thread

Igor M Podlesny

> Поделитесь, если найдёте решение.

from: poige
date: Dec. 16th, 2011 12:16 pm (UTC)
Link

Чё так официально? :-)

Я написал письмо нескольким разработчикам, которые могут иметь отношение, посмотрим.

Reply | Parent | Thread

Igor M Podlesny

> Это 3.1.*, да?

from: poige
date: Dec. 16th, 2011 04:10 pm (UTC)
Link

У тебя ядро самосборное, или дистр (какой)?

Reply | Parent | Thread

Anton Kovalenko

Re: > Это 3.1.*, да?

from: akovalenko
date: Dec. 16th, 2011 05:48 pm (UTC)
Link

Ядро я беру с liquorix.net (это очень неудобно для багрепорта, потому что непонятно, кто виноват и кому слать; зато там легче убедить сборщика что-то включить или выключить в его конфигурации).

А у тебя как?

Кстати, вот такой код: http://www.sw4me.com/private/rusage.c (если его собрать с -m64) заставляет проблему проявиться, когда он запущен под strace: на одной из машин, где поймать проблему «естественным путём» трудно, "Unexpected rusage" из-под strace выводится всегда.

Ещё кстати: ntpd запущен на обеих машинах, где наблюдается проблема.

Похоже, происходящее можно описать словами «ядро насчитывает отрицательное время для ru_stime, но так как внутри оно беззнаковое, преобразование в tv_sec и tv_nsec даёт нечто с 18446744073 или 18446744072 секундами» (первое из этих чисел — целая часть 2^64 * 10^(-9), если что).

Reply | Parent | Thread

Igor M Podlesny

> Кстати, вот такой код: http://www.sw4me.com/private/rusage.c

from: poige
date: Dec. 16th, 2011 05:57 pm (UTC)
Link

Отлично, дам ссылку разрабам.

> А у тебя как?

У меня самосбор, с -ck и -bfq, тоже ntpd (правда Openntpd)

Пока ответил Peter Zijlstra: «…
I recently got a similar report, I had a quick look and didn't find
anything obviously wrong. I didn't get around to looking harder.

Will poke at it soon..
…»

Сейчас собрал 3.0.13 из ubuntu-repo, посмотрю. Там в пр-цпе есть такой же патч, что и в 3.1.x, который вызывает подозрение, но вот и проверим.

Reply | Parent | Thread

Anton Kovalenko

Re: > Кстати, вот такой код: http://www.sw4me.com/private/rusage.c

from: akovalenko
date: Dec. 16th, 2011 06:12 pm (UTC)
Link

Я так и не собрался протестировать как следует (впрочем, сейчас снова стало интересно, так что продолжу, наверное). Из того, что пробовал:
  • clocksource не влияет (испробовано tsc, hpet, acpi_pm);
  • для того, чтобы проявился баг с моим примером под strace, иногда нужно дать системе поработать некоторое время (поэтому я и упоминаю ntpd, и поэтому же может возникать опасная иллюзия, что некий workaround помогает: перезагружаемся, проверяем, всё работает -- а через несколько минут опять сломано).
Имеет смысл попробовать debian или vanilla kernel, так как у нас патчи пересекаются, похоже. Ещё мне советовал умный человек (но не kernel developer) отключить cpufreq (чтобы вообще не запускался изначально, так как рассинхронизация накапливается), и этого я не успел попробовать.

Reply | Parent | Thread

Igor M Podlesny

> у нас патчи пересекаются, похоже

from: poige
date: Dec. 16th, 2011 06:17 pm (UTC)
Link

Дело в том, что как раз в vanilla были коммиты, которые… ну вот пример:
> commit bcd5cff7216f9b2de0a148cc355eac199dc6f1cf
> Author: Peter Zijlstra <a.p.zijlstra@NO-SPAM>
> Date:   Mon Oct 17 11:50:30 2011 +0200
>
>     cputimer: Cure lock inversion
>
>     There's a lock inversion between the cputimer->lock and rq->lock;
>     notably the two callchains involved are:

Reply | Parent | Thread

Igor M Podlesny

> иногда нужно дать системе поработать некоторое время

from: poige
date: Dec. 16th, 2011 06:58 pm (UTC)
Link

Fuck(!): Unexpected rusage: 0.429971 and 18446744073.706218 => 0
(up 1:12)

Reply | Parent | Thread

Anton Kovalenko

Потестировал 3.1.0-1-amd64 debian, 3.2.0-rc4 из experimental.

from: akovalenko
date: Dec. 17th, 2011 12:25 am (UTC)
Link

Похоже, upstream не виноват: на debian'овских ядрах полёт нормальный уже аномально долгое время (впрочем, есть ещё вероятность, что дело в опциях сборки ядра, а не в патчах; но это пока проверять лениво).

Так что есть идея отмотаться от upstream developers и домотаться до CK (так как отсутствующий у меня bfq тут явно ни при чём).

Reply | Parent | Thread

Igor M Podlesny

> Похоже, upstream не виноват

from: poige
date: Dec. 17th, 2011 12:59 am (UTC)
Link

Мда, если так, зря я разработчиков беспокоил… :-/

См. upd..

Reply | Parent | Thread

Igor M Podlesny

> "Unexpected rusage" из-под strace выводится всегда

from: poige
date: Dec. 16th, 2011 06:05 pm (UTC)
Link

У меня на 3.0.13 такого нет. Если будет не лениво, проверю на 3.1.5 :-)

Reply | Parent | Thread

Igor M Podlesny

> У меня на 3.0.13 такого нет.

from: poige
date: Dec. 17th, 2011 01:30 am (UTC)
Link

Вобщем, как раз есть (только не сразу).

> Если будет не лениво, проверю на 3.1.5 :-)

Проверяю на нём без -ck (BFS).

Reply | Parent | Thread

Igor M Podlesny

> Ядро я беру с liquorix.net

from: poige
date: Dec. 16th, 2011 06:07 pm (UTC)
Link

Не понял чего там добавлют в vanilla. :-) Это zen-kernel, или нет?

Reply | Parent | Thread

Anton Kovalenko

Re: > Ядро я беру с liquorix.net

from: akovalenko
date: Dec. 16th, 2011 06:19 pm (UTC)
Link

zen по большей части (иногда с накатами/откатами конкретных патчей). Да, на "add a misc fix for clocksource" в liquorix-3.1.0-5+ не стоит обращать внимания: это я попросил добавить чей-то коммит из приготовленных для 3.2, будучи ошибочно уверен, что это решит проблему (см. выше про коварный эффект перезагрузки).

Reply | Parent | Thread

Igor M Podlesny

> вот такой код: http://www.sw4me.com/private/rusage.c

from: poige
date: Dec. 17th, 2011 12:31 pm (UTC)
Link

/* local copy :) */

#include <stdio.h>
#include <string.h>
#include <sys/resource.h>
int main(int argc, char *argv[])
{
  struct rusage usage;
  int ret;
  while(1) {
    memset(&usage,0xFF,sizeof(usage));
    ret = getrusage(RUSAGE_SELF,&usage);
    if ((usage.ru_utime.tv_sec < 0) ||
    (usage.ru_stime.tv_sec < 0) ||
    (usage.ru_utime.tv_sec >= (1UL<<31)) ||
    (usage.ru_stime.tv_sec >= (1UL<<31)) ||
    (usage.ru_utime.tv_usec < 0) ||
    (usage.ru_stime.tv_usec < 0) ||
    (usage.ru_utime.tv_usec > 1000000)||
    (usage.ru_stime.tv_usec > 1000000)||
    (ret<0)) {
      printf("Unexpected rusage: %zu.%zu and %zu.%zu => %d \n",
         usage.ru_utime.tv_sec,
         usage.ru_utime.tv_usec,
         usage.ru_stime.tv_sec,
         usage.ru_stime.tv_usec,
         ret);
    }
  }
  return 0;
}

Reply | Parent | Thread

Igor M Podlesny

(no subject)

from: poige
date: Feb. 17th, 2012 03:52 pm (UTC)
Link

Ку!

Кон Коливас в почте указал на опцию

Processor type and features  ---> [*] Fine granularity task level IRQ time accounting

У меня была выключена. Со включенной на 3.2.6 с BFS (и не только с BFS) всё пучком.

Reply | Parent | Thread