Здесь лежит окончание "расследования" Новогодний детектив: странный хайзенбаг в «питоньих» часах.
Изначально хотел просто обновить статью и написать соответствующий комментарий, но понял что апдейт выходит чуть не длиннее самой статьи.
Напомню краткое содержание предыдущей части: python, как впрочем и всё на нем написанное, временами прыгает в будущее, а конкретно в 2023-й год в локальной временной зоне, и по некоторым данным в 2024-й в UTC/GMT (но это не точно) и побыв там некоторое время возвращается обратно в настоящее.
Во время прыжка оно ведет себя довольно стабильно (т.е. считает нано-, микро- и миллисекунды, а то и секунды, как будто время идет как ни в чём не бывало) в 2023-м т.е. локально, при том что в результате повторных прыжков время вновь продолжается как будто по возвращению оно (время) течет в какой-то параллельной вселенной. Однако странное его "отражение" в UTC/GMT, ну то что как будто бы в 2024-м, выглядит менее стабильно, ибо для него наблюдается странные дрейфы дополнительно к смещению прыжка.
Хотя куда уж страннее.
Всё это в результате хоть и выглядит как "битая память", вряд ли этим объясняется, ибо во время аномалий наблюдаются совершенно ненормальные величины промежуточных значений unix time, для которых во главу угла можно положить преобразование вида:
RT, UTC/GMT ==> t, UTC/GMT ==> lt, UTC-08:00
CLOCK_REALTIME ==> time(RT) ==> localtime(t)
---------------------------------------------------------------
1640M ==> 1705M ==> 1674MЧто как бы ни в целочисленной форме ни в формате с плавающей запятой простейшими битовыми операциями (& или |) не объяснить… Ну и как вишенка этот до странности стабильный результат для lt, при этом еще и "корректно" тикающий в течении временных аномалий.
"Расследование" затянулось чуть-чуть — праздники, ну и человек, у которого оно поломано, никуда не торопится по всей видимости занятой очень, т.к. отвечает с паузами в два-три дня.
Сразу скажу что python был полностью неувиноватым… Во-первых, выяснилось, что ваабще неувиновный он. Ваабще чистой воды неувиновный. Крайней степени неувиновный.
А если серьёзно, кто бы сомневался, однако лучше всё же по порядку...
Итак, что еще делалось на той машине чтобы поймать багу (для тех кто не видел апдейты первой части):
- переустановка Debian 11 а затем и Fedora 34 на той же VM с последующим тестом на чистых системах ничего не поменяла
- python 3.10.2 собранный из исходников показывает там тот же результат, аномалия воспроизводится с той же частотой и практически тем же дампом из под ltrace
- человек обращался с этим к хостеру — они ничего конкретного пока не ответили
Поскольку с ltrace дальнейшее продвижение не видится возможным, а товарищ уже сам собирал питон из исходников, захотелось мне "подебажить" его немного на предмет уточнить в котором месте конкретно то всё ломается, т.е. запустить тест на дебажном и несколько пропатченом python.
Чтобы не пугать человека gdb, conditional breakpoint и тому подобными конструкциями да из под консоли, на коленке была написана простенькая заплатка для python 3.10.2, с целью вывести некоторые промежуточные состояния и переменные в каждой функции в цепочке от clock_gettime до собственно местами кривого ответа time.time() и как он затем долетает до time.localtime():
diff --git a/Modules/timemodule.c b/Modules/timemodule.c
index 4caacc3b64..c975928fe7 100644
--- a/Modules/timemodule.c
+++ b/Modules/timemodule.c
@@ -70,7 +70,9 @@ static PyObject*
_PyFloat_FromPyTime(_PyTime_t t)
{
double d = _PyTime_AsSecondsDouble(t);
- return PyFloat_FromDouble(d);
+ PyObject* op = PyFloat_FromDouble(d);
+ printf("**** %-40s%.3lf ooo>> %.3lf (O:%p)\n", __FUNCTION__, d, PyFloat_AsDouble(op), op);
+ return op;
}
@@ -468,6 +470,7 @@ parse_time_t_args(PyObject *args, const char *format, time_t *pwhen)
else {
if (_PyTime_ObjectToTime_t(ot, &whent, _PyTime_ROUND_FLOOR) == -1)
return 0;
+ printf("**** %-40s%.ld.... <<ooo %.3lf (O:%p)\n", __FUNCTION__, whent, PyFloat_AsDouble(ot), ot);
}
*pwhen = whent;
return 1;
diff --git a/Python/pytime.c b/Python/pytime.c
index 1ef99aee74..7afa21df6b 100644
--- a/Python/pytime.c
+++ b/Python/pytime.c
@@ -292,7 +292,7 @@ _PyTime_FromNanosecondsObject(_PyTime_t *tp, PyObject *obj)
}
#ifdef HAVE_CLOCK_GETTIME
-static int
+int __attribute__((visibility("default")))
pytime_fromtimespec(_PyTime_t *tp, struct timespec *ts, int raise)
{
_PyTime_t t, nsec;
@@ -326,6 +326,8 @@ pytime_fromtimespec(_PyTime_t *tp, struct timespec *ts, int raise)
t += nsec;
}
+ printf("**** %-40s%ld\n", __FUNCTION__, t);
+
*tp = t;
return res;
}
@@ -338,7 +340,7 @@ _PyTime_FromTimespec(_PyTime_t *tp, struct timespec *ts)
#endif
#if !defined(MS_WINDOWS)
-static int
+int __attribute__((visibility("default")))
pytime_fromtimeval(_PyTime_t *tp, struct timeval *tv, int raise)
{
_PyTime_t t, usec;
@@ -655,7 +657,7 @@ _PyTime_AsTimespec(_PyTime_t t, struct timespec *ts)
}
#endif
-static int
+int __attribute__((visibility("default")))
py_get_system_clock(_PyTime_t *tp, _Py_clock_info_t *info, int raise)
{
#ifdef MS_WINDOWS
@@ -765,7 +767,7 @@ py_get_system_clock(_PyTime_t *tp, _Py_clock_info_t *info, int raise)
return 0;
}
-_PyTime_t
+_PyTime_t __attribute__((visibility("default")))
_PyTime_GetSystemClock(void)
{
_PyTime_t t;
@@ -777,10 +779,12 @@ _PyTime_GetSystemClock(void)
return t;
}
-int
+int __attribute__((visibility("default")))
_PyTime_GetSystemClockWithInfo(_PyTime_t *t, _Py_clock_info_t *info)
{
- return py_get_system_clock(t, info, 1);
+ int ret = py_get_system_clock(t, info, 1);
+ printf("**** %-40s%ld\n", __FUNCTION__, *t);
+ return ret;
}
#if __APPLE__Как заплата выглядит можно посмотреть в этом примере (вырезаны только релевантные куски кода из pytime.c и timemodule.c, которые тут немного упрощены и добавлены пояснения для наглядности):
// == составляющие time.time(), до результата 1640M (гуд) или 1705M (бэд) ==
// делает из длинного целого питоний объект с double (posix epoch секунды) внутри:
static PyObject*
_PyFloat_FromPyTime(_PyTime_t t)
{
double d = _PyTime_AsSecondsDouble(t); // фактически делим на 1e9
PyObject* op = PyFloat_FromDouble(d); // оборачиваем double в PyObject
+ printf("**** %-40s%.3lf ooo>> %.3lf (O:%p)\n", __FUNCTION__, d, PyFloat_AsDouble(op), op);
return op;
}
// делает из структуры timespec длинное целое (int64_t), наносекунды от posix epoch:
static int
pytime_fromtimespec(_PyTime_t *tp, struct timespec *ts, int raise)
{
_PyTime_t t;
t = (_PyTime_t)ts->tv_sec;
t *= SEC_TO_NS; // 1e9
t += ts->tv_nsec;
+ printf("**** %-40s%ld\n", __FUNCTION__, t);
*tp = t;
return res;
}
// системное время в наносекундах от posix epoch, когда defined(HAVE_CLOCK_GETTIME),
// что справедливо для нужной нам машинки:
static int
py_get_system_clock(_PyTime_t *tp, _Py_clock_info_t *info, int raise)
{
struct timespec ts;
...
err = clock_gettime(CLOCK_REALTIME, &ts);
if (err) {...}
if (pytime_fromtimespec(tp, &ts, raise) < 0) {
return -1;
}
if (info) {...}
...
return 0;
}
// платформо-независимая внутрянка time.time():
int
_PyTime_GetSystemClockWithInfo(_PyTime_t *t, _Py_clock_info_t *info)
{
int ret = py_get_system_clock(t, info, 1);
+ printf("**** %-40s%ld\n", __FUNCTION__, *t);
return ret;
}
// == составляющие time.localtime(), где наблюдается 1674M ==
static int
parse_time_t_args(PyObject *args, const char *format, time_t *pwhen)
{
PyObject *ot = NULL;
time_t whent;
if (!PyArg_ParseTuple(args, format, &ot))
return 0;
...
// PyObject в double и округляем до целого (в time_t, posix epoch секунды):
if (_PyTime_ObjectToTime_t(ot, &whent, _PyTime_ROUND_FLOOR) == -1)
return 0;
+ printf("**** %-40s%.ld.... <<ooo %.3lf (O:%p)\n", __FUNCTION__, whent, PyFloat_AsDouble(ot), ot);
...
*pwhen = whent;
return 1;
}
Скрипт для всего действа выглядит как то так:
cd /tmp/python-test
# клонируем (3.10.2) из репозитария в текущую папку:
git clone --branch v.3.10.2 --depth 1 https://github.com/python/cpython.git .
# накатываем patch (сначала сохранив содержимое в patch-debug-time.diff):
git apply patch-debug-time.diff
# собираем питон в папке build/debug:
mkdir -p ./build/debug && cd ./build/debug
../../configure CFLAGS='-DPy_DEBUG' --with-pydebug
make
# запускаем тест и ждем прыжка во времени:
printf 'typedef clockid_t = enum (CLOCK_REALTIME=0, CLOCK_MONOTONIC=1);\ntypedef timespec = struct(long, long);\ntypedef tm = struct(int, int, int, int, int, int, int, int, int);\nint clock_gettime(clockid_t, +timespec*);\ndouble floor(void*, double);\ntm* localtime_r(long*, +tm*);\n' > /tmp/ltrace.conf
ltrace -e '*gettime+floor+localtime_r' -F /tmp/ltrace.conf \
./python -c $'import time\nwhile True: t=time.time(); lt=time.localtime(t); print("%.3f\t%.3f\t%s" % (time.monotonic(), t, time.strftime("%Y-%m-%dT%H:%M:%S", lt))), time.sleep(0.5)'Заплатка и скрипт улетели до бенефициара и ожидаемо через пару дней прилетел ответ, где наглядно так прослеживается, что питон неуиноватый прыжки в будущее наблюдаются там где они тупо не должны наблюдаться (а они, как тот суслик, в наличии). Однако всё по порядку…
python->clock_gettime(CLOCK_MONOTONIC, { 1351882, 719005224 }) = 0
**** pytime_fromtimespec 1351882719005224
python->clock_gettime(CLOCK_REALTIME, { 1642516505, 739162789 }) = 0
**** pytime_fromtimespec 1642516505739162789
**** _PyTime_GetSystemClockWithInfo 1642516505739162789
**** _PyFloat_FromPyTime 1642516505.739 ooo>> 1642516505.739 (O:0x7f17b4b84400)
**** parse_time_t_args 1642516505.... <<ooo 1642516505.739 (O:0x7f17b4b84400)
python->localtime_r(1642516505, { 5, 35, 6, 18, 0, 122, 2, 17, 0 }) = { 5, 35, 6, 18, 0, 122, 2, 17, 0 }
python->clock_gettime(CLOCK_MONOTONIC, { 1351883, 222098983 }) = 0
**** pytime_fromtimespec 1351883222098983
**** _PyFloat_FromPyTime 1351883.222 ooo>> 1351883.222 (O:0x7f17b4b84220)
1351883.222 1642516505.739 2022-01-18T06:35:05 --
python->clock_gettime(CLOCK_MONOTONIC, { 1351883, 222672553 }) = 0
**** pytime_fromtimespec 1351883222672553
python->clock_gettime(CLOCK_REALTIME, { 1642516506, 243048649 }) = 0
**** pytime_fromtimespec 1642516506243048649
**** _PyTime_GetSystemClockWithInfo 1642516506243048649
**** _PyFloat_FromPyTime 1676140652.455 ooo>> 1676140652.455 (O:0x7f17b4b84220)
**** parse_time_t_args 1676140652.... <<ooo 1676140652.455 (O:0x7f17b4b84220)
python->localtime_r(1676140652, { 32, 37, 10, 11, 1, 123, 6, 41, 0 }) = { 32, 37, 10, 11, 1, 123, 6, 41, 0 }
python->clock_gettime(CLOCK_MONOTONIC, { 1351883, 724655853 }) = 0
**** pytime_fromtimespec 1351883724655853
**** _PyFloat_FromPyTime 1384655.922 ooo>> 1384655.922 (O:0x7f17b4b84400)
1415970.483 1707394536.366 2023-02-11T10:37:32 --
python->clock_gettime(CLOCK_MONOTONIC, { 1351883, 724982418 }) = 0
**** pytime_fromtimespec 1351883724982418
python->clock_gettime(CLOCK_REALTIME, { 1642516506, 751439357 }) = 0
**** pytime_fromtimespec 1642516506751439357
**** _PyTime_GetSystemClockWithInfo 1642516506751439357
**** _PyFloat_FromPyTime 1642516506.751 ooo>> 1642516506.751 (O:0x7f17b4b84400)
**** parse_time_t_args 1642516506.... <<ooo 1642516506.751 (O:0x7f17b4b84400)
python->localtime_r(1642516506, { 6, 35, 6, 18, 0, 122, 2, 17, 0 }) = { 6, 35, 6, 18, 0, 122, 2, 17, 0 }
python->clock_gettime(CLOCK_MONOTONIC, { 1351884, 293524900 }) = 0
**** pytime_fromtimespec 1351884293524900
**** _PyFloat_FromPyTime 1351884.294 ooo>> 1351884.294 (O:0x7f17b4b84220)
1351884.294 1642516506.751 2022-01-18T06:35:06 --
python->clock_gettime(CLOCK_MONOTONIC, { 1351884, 321497772 }) = 0
**** pytime_fromtimespec 1351884321497772
python->clock_gettime(CLOCK_REALTIME, { 1642516507, 359952744 }) = 0
**** pytime_fromtimespec 1642516507359952744
**** _PyTime_GetSystemClockWithInfo 1642516507359952744
**** _PyFloat_FromPyTime 1642516507.360 ooo>> 1642516507.360 (O:0x7f17b4b84220)
**** parse_time_t_args 1642516507.... <<ooo 1642516507.360 (O:0x7f17b4b84220)
python->localtime_r(1642516507, { 7, 35, 6, 18, 0, 122, 2, 17, 0 }) = { 7, 35, 6, 18, 0, 122, 2, 17, 0 }
python->clock_gettime(CLOCK_MONOTONIC, { 1351884, 863699790 }) = 0
**** pytime_fromtimespec 1351884863699790
**** _PyFloat_FromPyTime 1351884.864 ooo>> 1351884.864 (O:0x7f17b4b84400)
1351884.864 1642516507.360 2022-01-18T06:35:07 --
python->clock_gettime(CLOCK_MONOTONIC, { 1351884, 889163504 }) = 0
**** pytime_fromtimespec 1351884889163504
python->clock_gettime(CLOCK_REALTIME, { 1642516507, 918812741 }) = 0
**** pytime_fromtimespec 1642516507918812741
**** _PyTime_GetSystemClockWithInfo 1642516507918812741
**** _PyFloat_FromPyTime 1676140654.381 ooo>> 1676140654.381 (O:0x7f17b4b84400)
**** parse_time_t_args 1676140654.... <<ooo 1676140654.381 (O:0x7f17b4b84400)
python->localtime_r(1676140654, { 34, 37, 10, 11, 1, 123, 6, 41, 0 }) = { 34, 37, 10, 11, 1, 123, 6, 41, 0 }
python->clock_gettime(CLOCK_MONOTONIC, { 1351885, 400173973 }) = 0
**** pytime_fromtimespec 1351885400173973
**** _PyFloat_FromPyTime 1384657.598 ooo>> 1384657.598 (O:0x7f17b4b84220)
1415972.159 1707394538.291 2023-02-11T10:37:34 --
python->clock_gettime(CLOCK_MONOTONIC, { 1351885, 400525494 }) = 0
**** pytime_fromtimespec 1351885400525494
python->clock_gettime(CLOCK_REALTIME, { 1642516508, 421229660 }) = 0
**** pytime_fromtimespec 1642516508421229660
**** _PyTime_GetSystemClockWithInfo 1642516508421229660
**** _PyFloat_FromPyTime 1642516508.421 ooo>> 1642516508.421 (O:0x7f17b4b84220)
**** parse_time_t_args 1642516508.... <<ooo 1642516508.421 (O:0x7f17b4b84220)
python->localtime_r(1642516508, { 8, 35, 6, 18, 0, 122, 2, 17, 0 }) = { 8, 35, 6, 18, 0, 122, 2, 17, 0 }
python->clock_gettime(CLOCK_MONOTONIC, { 1351885, 902929970 }) = 0
**** pytime_fromtimespec 1351885902929970
**** _PyFloat_FromPyTime 1351885.903 ooo>> 1351885.903 (O:0x7f17b4b84400)
1351885.903 1642516508.421 2022-01-18T06:35:08 --Кстати, внимательный читатель возможно заметил, что цифры успели немного подрасти, что 1642M (которая месяц назад была еще 1640M), что 1676M (которая ранее была 1674M), и сделали они это пропорционально (что возможно еще один аргумент против битой памяти).
Берём первый кусок в котором наблюдаем 1676M вместо положенного 1642M и пытаемся через него выйти на того "мерцающего" вдалеке суслика.
Итак собственно выхлоп теста для первой аномалии (diff синтакс для ударения, т.е. подсветки первого следа зверька):
python->clock_gettime(CLOCK_REALTIME, { 1642516506, 243048649 }) = 0
**** pytime_fromtimespec 1642516506243048649
**** _PyTime_GetSystemClockWithInfo 1642516506243048649
- **** _PyFloat_FromPyTime 1676140652.455 ooo>> 1676140652.455 (O:0x7f17b4b84220)
**** parse_time_t_args 1676140652.... <<ooo 1676140652.455 (O:0x7f17b4b84220)
python->localtime_r(1676140652, { 32, 37, 10, 11, 1, 123, 6, 41, 0 }) = { 32, 37, 10, 11, 1, 123, 6, 41, 0 }
python->clock_gettime(CLOCK_MONOTONIC, { 1351883, 724655853 }) = 0
**** pytime_fromtimespec 1351883724655853
**** _PyFloat_FromPyTime 1384655.922 ooo>> 1384655.922 (O:0x7f17b4b84400)
1415970.483 1707394536.366 2023-02-11T10:37:32 --Т.е. смотрим выше в код для _PyFloat_FromPyTime, и что мы там видим? А собственно, то что _PyTime_AsSecondsDouble(t) вдруг возвращает 1676M вместо 1642M, которое затем, уже в испорченном виде, оборачивается в объект.
И это при верном t, которое было 1642516506243048649, что при делении на 1e9 вдруг почему-то даёт нам 1676140652.455!
Если же мы заглянем в _PyTime_AsSecondsDouble, которая по всей видимости и есть суть искомая машина времени, нам там наглядно продемонстрируют глубокий философский смысл фразы "Суслика видишь?.. Вот и я не вижу… А он есть":
double
_PyTime_AsSecondsDouble(_PyTime_t t)
{
/* volatile avoids optimization changing how numbers are rounded */
volatile double d;
if (t % SEC_TO_NS == 0) {
_PyTime_t secs;
/* Divide using integers to avoid rounding issues on the integer part.
1e-9 cannot be stored exactly in IEEE 64-bit. */
secs = t / SEC_TO_NS;
d = (double)secs;
}
else {
d = (double)t; /* Ты понимаешь, что это значит? */
d /= 1e9; /* Это значит, что эта пакость не работает! */
}
return d;
}Поскольку никакой магии тут нет и быть не может: volatile для d — это попытка избежать оптимизации, изменяющей порядок округления чисел, а первая ветка служит для предотвращения небольшой ошибки в расчетах на системах с 64-битным FP, если число делится на единицу с 9 нулями без остатка (имеем только круглые секунды). Т.е. деление организованно тут либо в целочисленной для int64_t, либо в FP арифметике для double (зависит от остатка при делении t на SEC_TO_NS, то есть на тот самый лярд).
Если короче, то на самом деле эта функция абсолютно детерминирована, что полностью исключает какие-либо отклонения от совершенно обычного действия деления t / 1e9. Что для 1642516506243048649 / 1e9 должно быть 1642516506.243 а никак не 1676140652.455.
Ну, в случае корректно работающей системы, естественно.
Отсюда вывод, что она (та система) работает некорректно. Как собственно в принципе и предполагалось...
"А где же тот 1707M (который результат time.time()) в промежуточных значениях" спросит цепкий и наблюдательный читатель. И я ему незамедлительно отвечу: либо мы до них еще не добрались (нужна еще парочка printf где-нибудь), либо это так не дебажится (хайзенбаг тут всё-таки или погулять вышел), либо, что скорее всего, мы имеем похожую ошибку в FP при округлении числа (или форматировании оного на %.3f) в питоньей реализации интерполяции %-оператором.
Как-то так.
В результате подозрение на следующие причины:
- либо FPU, например что-либо похожее на "broken AMD FPU FIP/FDP/FOP leak" XSA-172 (заметим что здесь как и у человека речь про AMD)
- либо поврежденная память (странно только что оно всё на удивление стабильно и при этом не проявляется нигде более, тем более если то, как оно выглядит, находится на стеке)
- либо hypervisor, к примеру что-нибудь из оперы LazyFP и т.п. или как если бы кто-то пробует сам хост или какую-либо виртуалку на нем на exploit в сторону векторов типа branch predictor attack (типа тех же meltdown/spectre) и тем самым вызывает поломку состояния машины/CPU/FPU и т.д.
На этом можно было бы и завершить, порекомендовав человеку либо как-то заставить провайдера сменить для виртуалки host, либо поменять собственно хостера.
Однако, захотелось помочь людям выяснить что это такое за беда.
Набросал на коленке небольшой скрипт, компилирующий простенький код на сях (безо всяких питонов) и запускающий его экзешник с целью проверить, что у нас тут собственно сломано FPU или память.
Если в результате теста time-jump будет воспроизведен (правильные наносекунды, но неверные секунды), это скорее всего будет сигнализировать о «сломанном» FPU, в противном же случае это может сигнализировать о «сломанной» памяти, так как по сравнению с python, этот код всегда использует одни и те же адреса памяти в стеке или вообще только регистры.
Пока без ответа, два дня еще не прошло.
[UPD] Всё — тема закрыта, суслик убег, магия кончилась: хост вылечился заменой CPU.
За сим позвольте откланяться, всем участвовавшим большое спасибо. Ах да, ниже небольшой опрос, как говорится «Messieurs, faites vos jeux»...
