stitrace
Май 5, 2012 10:37:14
Господа, помогите обьяснить такую аномалию.
C:\Program Files\Console2>python
Python 3.2.3 (default, Apr 11 2012, 07:15:24) [MSC v.1500 32 bit (Intel)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import time
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.016000032424926758
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.014999866485595703
>>>
ClockRes v2.0 - View the system clock resolution
Copyright (C) 2009 Mark Russinovich
SysInternals - www.sysinternals.com
Maximum timer interval: 15.625 ms
Minimum timer interval: 1.000 ms
Current timer interval: 0.977 ms
dehun
Май 5, 2012 11:14:49
time.sleep() скорей всего вызывает системный вызов слип. который говорит что поток уже не хочет дальше юзать свой квант времени и проснётся через столькото. в большинстве случаев поток сразу подхватывает управление. но в некоторых случаях второй поток другого процеса забирает управление и мы получаем что слип работает дольше чем мы ему сказали. на сколько дольше - непредсказуемо. если конкурируюшие процессы будут полностью утилизировать процессорное время то на квант_времени_потока * количество_конкурируюших_процессов_запушеных_перед_нами. обычно квант времени на виндах равен гдето 7/15 мс.
вышенаписаное лиш догадка. думаю надо лезть внутря библиотеки и смотреть что она там у себя вызывает.
dehun
Май 5, 2012 11:17:58
проверил у себя локально на линухах на питоне 2.7
In [2]: import time
In [3]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00108098983765
In [4]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107789039612
In [5]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107789039612
In [6]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107192993164
In [7]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107216835022
In [8]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00108003616333
In [9]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107789039612
In [10]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107192993164
In [11]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107097625732
In [12]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107192993164
In [13]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00108289718628
In [14]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107288360596
In [15]: t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107216835022
результат для 3го(3.1.4) питона такойже
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107598304749
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0010678768158
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107383728027
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.00106811523438
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107312202454
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0010781288147
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0010781288147
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107884407043
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0010678768158
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0010678768158
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107598304749
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107288360596
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.00107598304749
>>> t=time.time();time.sleep(0.001);print(time.time()-t)
0.0010678768158
dehun
Май 5, 2012 11:24:58
и сам питон мог кстати тоже быть переключеным на другой процесс во время интерпретирования
stitrace
Май 5, 2012 11:27:56
Да, на линухах всё в порядке, я тоже проверял. А вот Win выдаёт такие перлы, причём это происходит не только на слипе. А вообще любая операция в приложении с несколькими тредами может занимать от 0 до 15 миллисекунд. При этом я выставляю принудительно квантование в 1 миллисекунду. Вообще, это конечно, возмутительно всё. На линух перейти не получится, т.к. приложение использует COM либу, которая есть только для win.
stitrace
Май 5, 2012 11:34:34
Такс. Что то совсем непонятное происходит. Попробовал вот так:
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0010501344570821303
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0012665396496620573
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0015909444136923412
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0015294380658179563
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0019364262628780438
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0013224009428061123
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.00175521454207761
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0019952209703042456
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0013691298680420516
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0014522896987667622
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0016494927057486564
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0011523614806350224
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0018497084084785342
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0014535999857159254
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0015459928932379796
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0014179961787768036
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0018297509062001893
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0018857782618795227
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0018481377783317043
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0013559980715314168
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0017300908879853694
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0013515904505148058
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.001234491723657527
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0011666771422937927
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.001518978269022142
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0011990754066744103
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0016044276199487228
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0018640058568273332
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.001941608485260815
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0019550188382773115
>>> t=time.clock();time.sleep(0.001);print(time.clock()-t)
0.0018569337356950655
>>>
Получается, что time.time в win имеет погрешность 15 миллисекунд… Где бы ещё узнать эти погрешности…
dehun
Май 5, 2012 11:39:17
глянул что там вызывается. в модуле тайм функция слип реализована по разному для разных платформ. вернее она вызывает флоатслип которая уже реализована по разному.
код там такой
static int
floatsleep(double secs)
{
/* XXX Should test for MS_WINDOWS first! */
#if defined(HAVE_SELECT) && !defined(__EMX__)
struct timeval t;
double frac;
int err;
frac = fmod(secs, 1.0);
secs = floor(secs);
t.tv_sec = (long)secs;
t.tv_usec = (long)(frac*1000000.0);
Py_BEGIN_ALLOW_THREADS
err = select(0, (fd_set *)0, (fd_set *)0, (fd_set *)0, &t);
Py_END_ALLOW_THREADS
if (err != 0) {
#ifdef EINTR
if (errno == EINTR) {
if (PyErr_CheckSignals())
return -1;
}
else
#endif
{
PyErr_SetFromErrno(PyExc_IOError);
return -1;
}
}
#elif defined(__WATCOMC__) && !defined(__QNX__)
/* XXX Can't interrupt this sleep */
Py_BEGIN_ALLOW_THREADS
delay((int)(secs * 1000 + 0.5)); /* delay() uses milliseconds */
Py_END_ALLOW_THREADS
#elif defined(MS_WINDOWS)
{
double millisecs = secs * 1000.0;
unsigned long ul_millis;
if (millisecs > (double)ULONG_MAX) {
PyErr_SetString(PyExc_OverflowError,
"sleep length is too large");
return -1;
}
Py_BEGIN_ALLOW_THREADS
/* Allow sleep(0) to maintain win32 semantics, and as decreed
* by Guido, only the main thread can be interrupted.
*/
ul_millis = (unsigned long)millisecs;
if (ul_millis == 0 || !_PyOS_IsMainThread())
Sleep(ul_millis);
else {
DWORD rc;
HANDLE hInterruptEvent = _PyOS_SigintEvent();
ResetEvent(hInterruptEvent);
rc = WaitForSingleObject(hInterruptEvent, ul_millis);
if (rc == WAIT_OBJECT_0) {
Py_BLOCK_THREADS
errno = EINTR;
PyErr_SetFromErrno(PyExc_IOError);
return -1;
}
}
Py_END_ALLOW_THREADS
}
#elif defined(PYOS_OS2)
/* This Sleep *IS* Interruptable by Exceptions */
Py_BEGIN_ALLOW_THREADS
if (DosSleep(secs * 1000) != NO_ERROR) {
Py_BLOCK_THREADS
PyErr_SetFromErrno(PyExc_IOError);
return -1;
}
Py_END_ALLOW_THREADS
#else
/* XXX Can't interrupt this sleep */
Py_BEGIN_ALLOW_THREADS
sleep((int)secs);
Py_END_ALLOW_THREADS
#endif
return 0;
}
dehun
Май 5, 2012 11:43:42
DWORD rc;
HANDLE hInterruptEvent = _PyOS_SigintEvent();
ResetEvent(hInterruptEvent);
rc = WaitForSingleObject(hInterruptEvent, ul_millis);
if (rc == WAIT_OBJECT_0) {
Py_BLOCK_THREADS
errno = EINTR;
PyErr_SetFromErrno(PyExc_IOError);
return -1;
вот этот код поидеи вызывается на виндах в нашем случае. у нас получается 1 милисикунда.
тут мы вызываем WaitForSingleObject что практически 100% может дасть нам погрешность в квант времени конкурируюших процессов/потоков.
stitrace
Май 5, 2012 12:00:01
Спасибо, с этим понятно. Но если квант времени в системе 1 ms, то неясно всё равно, откуда в случае time.time() берется 15 ms периодически (то есть не в 100% случаев).
dehun
Май 5, 2012 12:27:04
а как задавался квант времени и как выснилось что он 1мс?