cerrar-sesion editar-perfil marker video calendario monitor periodico fax rss twitter facebook google-plus linkedin alarma circulo-derecha abajo derecha izquierda mover-vertical candado usuario email lupa exito mapa email2 telefono etiqueta

400430404. Registros en C++

Escrito por Redacción en Tema de portada
no hay comentarios Haz tu comentario
Imagen de logotipo de facebook Imagen de logotipo de Twitter Imagen de Logotipo de Google+ Imagen de logotipo de Linkedin

Los registros son una técnica fundamental para localizar averías y mantener los sistemas de software. Son sencillos, proporcionan información sin necesidad de tener conocimientos de lenguajes de programación y no necesitan herramientas especializadas. El registro es un medio útil para averiguar si una aplicación está haciendo realmente lo que se supone que debe hacer. Los buenos mecanismos de registro pueden ahorrar largas sesiones de depurado y aumentar drásticamente la facilidad de mantenimiento de las aplicaciones.

En el presente artículo voy a presentar una plataforma de registros sencilla pero muy útil, que es segura de introducir, segura en los hilos (a nivel de línea) eficiente, portátil, de baja granularidad, compacta y flexible. El código fuente completo, que funciona con Visual C++ 7.1, g++ 3.3.5, y CC 5.3 en Sun y otras plataformas, está disponible online en: www.ddj.com/code/.

El primer paso

Vamos a dedicarnos primero a la clase Log. El Listado número 1 usa una variable de miembro std::ostringstream denominada “os” para acumular los datos registrados. La función de miembro Get() da acceso a esa variable.

((En el presente artículo voy a presentar una plataforma de registros sencilla pero muy útil, que es segura de introducir, segura en los hilos, eficiente y portátil))

Después de que se formatean todos los datos, el destructor de Log persiste con el resultado al error estándar. La clase Log se usa de la manera siguiente:

Log().Get(logINFO) << “Hello “ << username;

La ejecución de este código crea un objeto Log con el nivel de registro logINFOx, toma el objeto std::stringstream, formatea y acumula los datos del usuario suministrado, y por último, persiste con la cadena resultante hasta dentro del fichero de registro usando exactamente una invocación a fprintf().

¿Por qué alinear durante la destrucción? Los dos últimos pasos son importantes porque confieren seguridad de hilado al mecanismo de registro. La función fprintf() es segura en los hilos, así que incluso si el registro se utiliza desde distintos hilos, las líneas de resultados no estarán revueltas. Según gnu.org/software/libc/manual/html_node/Streams-and-Threads.html:

El estándar POSIX requiere que, por defecto, las operaciones de flujo sean atómicas...emitir dos operaciones de flujo para el mismo flujo en dos hilos a la vez hará que las operaciones se ejecuten como si fueran emitidas de forma secuencial. Las operaciones de búfer realizadas mientras se lee o escribe están protegidas de otros usos del mismo flujo. Para hacer esto, cada flujo tiene un objeto de bloqueo interno que tiene que ser (implícitamente) adquirido antes de poder hacer cualquier trabajo.

Antes de pasar a una implementación más eficiente, vamos a escribir código para insertar etiquetas en proporción al nivel de registro, y añadir un std::endl a cada porción de texto. Esto hace que la línea de registro esté orientada y sea fácil de leer tanto para humanos como para máquinas. Aquí tenemos el código pertinente:

Log::ReportingLevel() = logDEBUG2;

const int count = 3;

Log().Get(logDEBUG) << “A loop with “ << count << “ iterations”; for (int i = 0; i != count; ++i)

Log().Get(logDEBUG1) << “the counter i = “ << i;

que produce:
- 22:25:23.643 DEBUG: A loop with 3 iterations
- 22:25:23.644 DEBUG1: the counter i = 0
- 22:25:23.645 DEBUG1: the counter i = 1
- 22:25:23.645 DEBUG1: the counter i = 2

La indentación hace que el registro sea más legible. Más etiquetas principales implican un nivel de registro más detallado.

Un pequeño truco

Hasta ahora, la plataforma ha mostrado buenos resultados con sólo pequeñas inversiones: Ofrece algunas buenas normas de formateado (las etiquetas según el nivel de registro y std::endl final) en un paquete pequeño y fácil de usar. No obstante, el Log actual tiene un problema de eficacia: Si el nivel de registro se fija para que no haga realmente nada, Log acumula los datos internamente – sólo para notar más tarde, durante la destrucción, que no se necesitan resultados. Sólo esta cuestión es lo suficientemente importante como para ser un impedimento al uso de Log en un sistema de producción.

((Antes de pasar a una implementación más eficiente, vamos a escribir código para insertar etiquetas en proporción al nivel de registro))

Podemos emplear un pequeño truco que hace que el código, cuando el registro no es necesario, sea casi tan rápido como el código sin ningún registro. El registro tendrá un coste sólo si realmente produce resultados, de lo contrario, el coste es bajo (y realmente inmensurable en la mayoría de los casos). Esto nos permite controlar el equilibrio entre ejecución rápida y registro detallado.

//listado 1

// Log, version 0.1: a simple logging class

enum TLogLevel logERROR, logWARNING, logINFO, logDEBUG, logDEBUG1,

logDEBUG2, logDEBUG3, logDEBUG4;

class Log

public:

Log();

virtual ~Log();

std::ostringstream& Get(TLogLevel level = logINFO);

public:

static TLogLevel& ReportingLevel();

protected:

std::ostringstream os;

private:

Log(const Log&);

Log& operator =(const Log&);

private:

TLogLevel messageLevel;

;

std::ostringstream& Log::Get(TLogLevel level)

os << "- " << NowTime(); os << " " << ToString(level) << ": "; os << std::string(level > logDEBUG ? 0 : level - logDEBUG, '\t');

messageLevel = level;

return os;

Log::~Log()

if (messageLevel >= Log::ReportingLevel())

os << std::endl; fprintf(stderr, "%s", os.str().c_str()); fflush(stderr);

Vamos a trasladar la comprobación siguiente del destructor al momento más anterior posible, que es justo antes de la construcción del objeto Log. De esta forma, si el nivel de registro dice que deberíamos descartar los datos registrados, ni siquiera tendremos que crear el objeto Log.

#define LOG(level) \

if (level > Log::ReportingLevel()) ; \

else Log().Get(level)

Ahora el primer ejemplo se convierte en:

LOG(logINFO) << “Hello “ << username;

y es expandido por el preprocesador a (se añaden nuevas líneas para mayor claridad):

if (logINFO > Log::ReportingLevel())

;

else

Log().Get(logINFO) << “Hello “ << username;

En consecuencia, la clase Log se hace más simple ya que el miembro messageLevel y la prueba en el destructor no se necesitan más:

Log::~Log()

os << std::endl; fprintf(stderr, “%s”, os.str().c_str()); fflush(stderr);

El registro es mucho más eficaz ahora: Podemos añadir registros con toda liberalidad al código sin tener graves problemas de eficacia: Lo único que hay que recordar es pasar unos niveles de registro más elevados (es decir, más detallados) al código que más se ejecuta.

((Lo único que hay que recordar es pasar unos niveles de registro más elevados (es decir, más detallados) al código que más se ejecuta))

Después de aplicar este truco, convendría evitar los peligros relacionados con las macros – conviene no olvidar que el código de registro podría no ejecutarse, dependiendo del nivel de registro en efecto. Eso es lo que realmente queríamos, y es lo que realmente hace que el código sea eficiente. Pero, como siempre, la “macro-itis” puede introducir fallos técnicos muy sutiles. En el siguiente ejemplo:

LOG(logINFO) << “A number of “ << NotifyClients() << “ were notified.”; se notificará a los clientes sólo si el detalle del nivel de registro es logINFO o más bajo. Probablemente no es eso lo que se pretendía. El código correcto debería ser:

const int notifiedClients = NotifyClients();

LOG(logINFO) << “A number of “ << notifiedClients << “ were notified.”;

//listado 2

class Output2FILE // implementation of OutputPolicy

public:

static FILE*& Stream();

static void Output(const std::string& msg);

;

inline FILE*& Output2FILE::Stream()

static FILE* pStream = stderr;

return pStream;

inline void Output2FILE::Output(const std::string& msg)

FILE* pStream = Stream();

if (!pStream)

return

fprintf(pStream, "%s", msg.c_str());

fflush(pStream);

typedef Log FILELog;

#define FILE_LOG(level) \

if (level > FILELog::ReportingLevel() || !Output2FILE::Stream()) ; \

else FILELog().Get(messageLevel)

Cómo hacerse genérico

Otra cuestión con la implementación que hemos compilado hasta ahora es que el código es cableado para conectar a stderr, sólo stderr, y nada más que stderr. Si nuestra biblioteca es parte de una aplicación GUI, tendría más sentido poder conectar a un fichero ASCII . El cliente (no la biblioteca) debería especificar cual es el destino de la conexión. No es difícil poner a Log en parámetros para permitir que cambie el destino de FILE*, pero ¿por qué darle un pez a Log en vez de enseñarle a pescar? Un método mejor es separar completamente nuestra lógica específica de Log de los detalles del output de bajo nivel. La comunicación puede hacerse de manera eficiente mediante una clase de política. El uso de un diseño basado en política está justificado (en vez de un método más dinámico mediante el polimorfismo en tiempo de ejecución) con el argumento de que, a diferencia del nivel de registro, es más probable que decidamos la estrategia para el registro al inicio, en el momento del diseño. Así que vamos a cambiar Log para definir y usar una política. De hecho, la interfaz de política es muy sencilla y modela un sencillo sink de cadenas:

static void Output(const std::string& msg);

La Log class toma la forma de una plantilla de clase que espera una implementación de la política:

template

class Log

//...

;

template

Log::~Log()

OutputPolicy::Output(msg.str());

Eso es poco más o menos todo lo que necesitamos hacer en Log. Podemos ahora suministrar el resultado de FILE* simplemente como una implementación de la política OutputPolicy; véase el Listado número 2. El código que aparece a continuación muestra cómo podemos cambiar el resultado de un stderr por defecto a algún fichero específico (comprobación/gestión de errores se omite en aras de la brevedad):

FILE* pFile = fopen(“application.log”, “a”);

Output2FILE::Stream() = pFile;

FILE_LOG(logINFO) << ...;

Una nota para las aplicaciones de multihilado: La implementación de la política Output2FILE es buena si no tenemos que establecer el destino del registro de manera concurrente. Si, por otro lado, planeamos cambiar de forma dinámica el flujo de registro en el tiempo de ejecución de los hilos arbitrarios, deberíamos usar un interbloqueo adecuado con el servicio de hilado de nuestra plataforma, o un envoltorio más portátil como los hilos Boost.

((No hace falta decir que el registro interbloqueado será más lento, pero el registro no utilizado irá igual de rápido que siempre))

El listado número 3 muestra cómo podemos hacerlo con hilos Boost:

No hace falta decir que el registro interbloqueado será más lento, pero el registro no utilizado irá igual de rápido que siempre. Eso es porque la prueba en la macro no está sincronizada – una condición de carrera benigna que no hace daño, asumiendo que los enteros están asignados atómicamente (una suposición correcta en la mayoría de las plataformas).

Nivel de registro de meseta en tiempo de compilación

A veces, podemos notar que la marca de la aplicación aumentó más de lo que podemos permitirnos, o que la comparación del tiempo de ejecución incurrida por sentencias de registro incluso no usadas es importante. Vamos a proporcionar un medio de eliminar algo del registro (en el momento de compilación) por medio de un símbolo de pre-procesador FILELOG_MAX_LEVEL:

#ifndef FILELOG_MAX_LEVEL

#define FILELOG_MAX_LEVEL logDEBUG4

#endif

#define FILE_LOG(level) \

if (level > FILELOG_MAX_LEVEL) ;\

else if (level > FILELog::ReportingLevel() || !Output2FILE::Stream()) ; \

else FILELog().Get(level)

Este código es interesante porque combina dos pruebas. Si pasamos una constante de tiempo de compilación a FILE_LOG, la primera prueba es frente a dos constantes de ese tipo y cualquier optimizador lo toma de forma estática y descarta totalmente la rama muerta del código generado. Esta optimización está tan extendida que podemos contar con ella con seguridad en la mayoría de los entornos a los que llevamos el código. La segunda prueba examina el nivel de registro en el tiempo de ejecución, como antes. Efectivamente, FILELOG_MAX_LEVEL impone una meseta estática en la gama de niveles de registro permitida de forma dinámica: Cualquier nivel de registro por encima de la meseta estática es simplemente eliminada del código. Como ejemplo:

bash-3.2$ g++ main.cpp

bash-3.2$ ./a.exe DEBUG1
- 22:25:23.643 DEBUG: A loop with 3 iterations
- 22:25:23.644 DEBUG1: the counter i = 0
- 22:25:23.645 DEBUG1: the counter i = 1
- 22:25:23.645 DEBUG1: the counter i = 2

bash-3.2$ g++ main.cpp -DFILELOG_MAX_LEVEL=3

bash-3.2$ ./a.exe DEBUG1
- 22:25:31.972 DEBUG: A loop with 3 iterations

Consejos finales sobre el uso de registros

He estado usando una interesante técnica que nos permite comparar distintas ejecuciones al pasar de hecho por diff los ficheros de registro desde cada ejecución. Esto es particularmente útil cuando no tenemos ni idea de lo que podría salir mal y por qué obtenemos resultados diferentes cuando ejecutamos el mismo código:
- En distintas plataformas (Linux frente a Windows).
- En versiones diferentes de la misma plataforma (REEL3 frente a RHEL4)
- Con distintas configuraciones de compilador (depurar frente a optimizar).

Sólo tenemos que poner la verbosidad al máximo nivel de detalle (conviene recordar que, como el registro es tan ligero, ya tenemos muchas sentencias de registro en logDEBUGx en el código), ejecutar la aplicación en los dos contextos distintos, eliminar las dataciones de los ficheros de registro, (usando por ejemplo el programa sed), y comparamos los dos resultados. Aunque los ficheros de resultados pueden ser enormes, es la diferencia que existe entre ellos lo que importa, y esa diferencia tiende a ser pequeña y altamente informativa.

//listado 3

#include

class Output2FILE

public:

static void Output(const std::string& msg);

static void SetStream(FILE* pFile);

private:

static FILE*& StreamImpl();

static boost::mutex mtx;

;

inline FILE*& Output2FILE::StreamImpl()

static FILE* pStream = stderr;

return pStream;

inline void Output2FILE::SetStream(FILE* pFile)

boost::mutex::scoped_lock lock(mtx);

StreamImpl() = pFile;

inline void Output2FILE::Output(const std::string& msg)

boost::mutex::scoped_lock lock(mtx);

FILE* pStream = StreamImpl();

if (!pStream)

return;

fprintf(pStream, "%s", msg.c_str());

fflush(pStream);

Otro buen resultado al usar esta plataforma de registro es la combinación del registro de múltiples y distintas aplicaciones (o múltiples ejemplos de una sola aplicación) en un solo fichero único. Sólo tenemos que abrir el mismo fichero desde varias aplicaciones en modo añadido, y ahí lo tenemos – registros muy bien intercalados desde varios procesos. El fichero de registro que resulta sigue teniendo significado y (al menos en un sistema operativo decente) mantiene las líneas de registro como unidades atómicas.

He realizado algunas mediciones para ver en realidad la rapidez del mecanismo del tiempo de ejecución (frente al tiempo de compilación). Los resultados fueron muy buenos. Ejecuté el código en tres configuraciones distintas:
- off-INFO. Registro desactivado en el tiempo de compilación, usado como una línea base.
- on-INFO. Registro activado en el tiempo de compilación, desactivado en el tiempo de ejecución (mediante un nivel de detalle INFO).
- on-DEBUG4. Registro activado en el tiempo de compilación, (mediante un nivel de detalle DEBUG4).

Cada configuración se ejecutó múltiples (20) veces (para eliminar los posibles errores aleatorios). La Figura 1 y la Tabla 1 ilustran los resultados. Como podemos ver, el resultado del tiempo de ejecución (25,109 sec.) coincide con el tiempo de compilación (25,109 sec.) Ello implica que realmente pagaremos por el registro sólo si lo vamos a utilizar.

Encontré muy útil en la práctica producir también la ID del hilo de donde procede el resultado junto con el nivel de datación y de registro. Ello sirve de gran ayuda cuando leemos un fichero de registro que procede de una aplicación de hilos múltiples. DDJ

Petru Marginean es un subdirector de Morgan Stanley, en donde trabaja como programador jefe de banca de inversión. Se puede contactar con él en: petru.marginean@gmail.com.

Noticias relacionadas

Comentarios

No hay comentarios.

Deja un comentario

Tu dirección de correo electrónico no será publicada. Los campos necesarios están marcados *

Debes haber iniciado sesión para comentar una noticia.