values setlevel practices logger info example best python logging timer timestamp

setlevel - Marca de tiempo precisa en el registro de Python



python logging best practices (8)

"la marca de tiempo debe ser precisa en relación con la otra"

¿Por qué tiempo? ¿Por qué no un número de secuencia? Si se trata de un cliente de la aplicación cliente-servidor, la latencia de la red hace que las marcas de tiempo sean aleatorias.

¿Estás buscando una fuente externa de información? ¿Di un registro en otra aplicación? De nuevo, si hay una red, esos tiempos no serán demasiado cercanos.

Si debe unir elementos entre aplicaciones separadas, considere pasar GUID para que ambas aplicaciones registren el valor GUID. Entonces podría estar absolutamente seguro de que coinciden, independientemente de las diferencias de tiempo.

Si desea que el pedido relativo sea ​​exactamente correcto, tal vez sea suficiente para que su registrador asigne un número de secuencia a cada mensaje en el orden en que se recibieron.

He estado construyendo una aplicación de registro de errores recientemente y estaba buscando una forma de marcar con precisión los datos entrantes. Cuando digo con precisión me refiero a que cada marca de tiempo debe ser precisa en relación con la otra (no es necesario sincronizarla con un reloj atómico ni nada de eso).

He estado usando datetime.now () como primera puñalada, pero esto no es perfecto:

>>> for i in range(0,1000): ... datetime.datetime.now() ... datetime.datetime(2008, 10, 1, 13, 17, 27, 562000) datetime.datetime(2008, 10, 1, 13, 17, 27, 562000) datetime.datetime(2008, 10, 1, 13, 17, 27, 562000) datetime.datetime(2008, 10, 1, 13, 17, 27, 562000) datetime.datetime(2008, 10, 1, 13, 17, 27, 578000) datetime.datetime(2008, 10, 1, 13, 17, 27, 578000) datetime.datetime(2008, 10, 1, 13, 17, 27, 578000) datetime.datetime(2008, 10, 1, 13, 17, 27, 578000) datetime.datetime(2008, 10, 1, 13, 17, 27, 578000) datetime.datetime(2008, 10, 1, 13, 17, 27, 609000) datetime.datetime(2008, 10, 1, 13, 17, 27, 609000) datetime.datetime(2008, 10, 1, 13, 17, 27, 609000) etc.

Los cambios entre relojes para el primer segundo de muestras se ven así:

uSecs difference 562000 578000 16000 609000 31000 625000 16000 640000 15000 656000 16000 687000 31000 703000 16000 718000 15000 750000 32000 765000 15000 781000 16000 796000 15000 828000 32000 843000 15000 859000 16000 890000 31000 906000 16000 921000 15000 937000 16000 968000 31000 984000 16000

Parece que los datos del temporizador solo se actualizan cada ~ 15-32 ms en mi máquina. El problema surge cuando analizamos los datos porque ordenar por fecha distinta de la marca de tiempo y luego ordenar por marca de tiempo nuevamente puede dejar los datos en el orden incorrecto (cronológicamente). Sería bueno tener las marcas de tiempo precisas hasta el punto de que cualquier llamada al generador de marca de tiempo proporcione una marca de tiempo única.

Había estado considerando algunos métodos que implican el uso de una llamada time.clock () agregada a una fecha de inicio de inicio, pero agradecería una solución que funcione con precisión a través de subprocesos en la misma máquina. Cualquier sugerencia sería muy gratamente recibida.

Gracias a todos por sus contribuciones. Todos fueron muy útiles. La respuesta de Brian parece más cercana a lo que eventualmente llegué (es decir, tratar con ella pero usar un tipo de identificador único, ver más abajo), así que acepté su respuesta. Logré consolidar todos los diversos receptores de datos en un único hilo, que es donde el sello de tiempo ahora se hace usando mi nueva clase AccurrateTimeStamp . Lo que he hecho funciona siempre que la marca de tiempo sea lo primero que use el reloj.

Como estipula S.Lott, sin un sistema operativo en tiempo real, nunca van a ser absolutamente perfectos. Realmente solo quería algo que me permitiera ver en relación con cada fragmento entrante de datos, cuando se recibían las cosas, por lo que lo que he descrito a continuación funcionará bien.

Gracias de nuevo a todos!

import time class AccurateTimeStamp(): """ A simple class to provide a very accurate means of time stamping some data """ # Do the class-wide initial time stamp to synchronise calls to # time.clock() to a single time stamp initialTimeStamp = time.time()+ time.clock() def __init__(self): """ Constructor for the AccurateTimeStamp class. This makes a stamp based on the current time which should be more accurate than anything you can get out of time.time(). NOTE: This time stamp will only work if nothing has called clock() in this instance of the Python interpreter. """ # Get the time since the first of call to time.clock() offset = time.clock() # Get the current (accurate) time currentTime = AccurateTimeStamp.initialTimeStamp+offset # Split the time into whole seconds and the portion after the fraction self.accurateSeconds = int(currentTime) self.accuratePastSecond = currentTime - self.accurateSeconds def GetAccurateTimeStampString(timestamp): """ Function to produce a timestamp of the form "13:48:01.87123" representing the time stamp ''timestamp'' """ # Get a struct_time representing the number of whole seconds since the # epoch that we can use to format the time stamp wholeSecondsInTimeStamp = time.localtime(timestamp.accurateSeconds) # Convert the whole seconds and whatever fraction of a second comes after # into a couple of strings wholeSecondsString = time.strftime("%H:%M:%S", wholeSecondsInTimeStamp) fractionAfterSecondString = str(int(timestamp.accuratePastSecond*1000000)) # Return our shiny new accurate time stamp return wholeSecondsString+"."+fractionAfterSecondString if __name__ == ''__main__'': for i in range(0,500): timestamp = AccurateTimeStamp() print GetAccurateTimeStampString(timestamp)

time.clock () solo mide el tiempo de reloj de pared en Windows. En otros sistemas, time.clock () realmente mide el tiempo de CPU. En esos sistemas, time.time () es más adecuado para el tiempo de reloj de pared, y tiene una resolución tan alta como Python puede manejar, que es tan alta como el sistema operativo puede administrar; usualmente usando gettimeofday (3) (resolución de microsegundos) o ftime (3) (resolución de milisegundos). Otras restricciones del sistema operativo realmente hacen que la resolución real sea mucho más alta que eso. datetime.datetime.now () usa time.time (), por lo que time.time () directamente no será mejor.

Para el registro, si uso datetime.datetime.now () en un bucle, veo aproximadamente una resolución de 1/10000 de segundo. Al mirar sus datos, tiene una resolución mucho más grosera que eso. No estoy seguro de si hay algo que Python pueda hacer, aunque es posible que pueda convencer al sistema operativo para que lo haga mejor por otros medios.

Me parece recordar que en Windows, time.clock () es en realidad (un poco) más preciso que time.time (), pero mide wallclock desde la primera llamada a time.clock (), por lo que debe recordar ''inicializar'' ''es primero.

Es poco probable que obtenga un control lo suficientemente preciso como para eliminar por completo la posibilidad de marcas de tiempo duplicadas; necesitará una resolución inferior al tiempo que lleva generar un objeto datetime. Hay un par de otros enfoques que podría tomar para enfrentarlo:

  1. Tratar con él. Deje sus marcas de tiempo no únicas tal como están, pero confíe en que el tipo de python sea estable para hacer frente a los problemas de reordenamiento. Ordenando primero la marca de tiempo, luego otra cosa retendrá la ordenación de la marca de tiempo; solo debes tener cuidado de comenzar siempre desde la lista ordenada de la marca de tiempo cada vez, en lugar de hacer múltiples ordenaciones en la misma lista.

  2. Agregue su propio valor para imponer la singularidad. P.ej. incluir un valor entero creciente como parte de la clave, o anexar tal valor solo si las marcas de tiempo son diferentes. P.ej.

Lo siguiente garantizará valores únicos de marca de tiempo:

class TimeStamper(object): def __init__(self): self.lock = threading.Lock() self.prev = None self.count = 0 def getTimestamp(self): with self.lock: ts = str(datetime.now()) if ts == self.prev: ts +=''.%04d'' % self.count self.count += 1 else: self.prev = ts self.count = 1 return ts

Para procesos múltiples (en lugar de hilos), se vuelve un poco más complicado.

Quería agradecer a J. Cage por esta última publicación.

Para mi trabajo, el calendario "razonable" de eventos en todos los procesos y plataformas es esencial. Obviamente, hay muchos lugares donde las cosas pueden ir mal (deriva del reloj, cambio de contexto, etc.); sin embargo, creo que esta precisa solución de temporización ayudará a garantizar que las marcas de tiempo registradas sean lo suficientemente precisas para ver las otras fuentes de error. .

Dicho esto, hay un par de detalles sobre los que me pregunto que se explican en When MicroSeconds Matter . Por ejemplo, creo que time.clock () finalmente se ajustará. Creo que para que esto funcione en un proceso de larga ejecución, es posible que tenga que manejar eso.

Hace unos años, desde que se formuló y respondió la pregunta, y se ha resuelto esto, al menos para CPython en Windows. Usando la secuencia de comandos a continuación en Win7 64bit y Windows Server 2008 R2, obtuve los mismos resultados:

  • datetime.now() da una resolución de 1ms y un jitter menor que 1ms
  • time.clock() da una resolución de mejor que 1us y un jitter mucho más pequeño que 1ms

La secuencia de comandos:

import time import datetime t1_0 = time.clock() t2_0 = datetime.datetime.now() with open(''output.csv'', ''w'') as f: for i in xrange(100000): t1 = time.clock() t2 = datetime.datetime.now() td1 = t1-t1_0 td2 = (t2-t2_0).total_seconds() f.write(''%.6f,%.6f/n'' % (td1, td2))

Los resultados visualizados: