Enseñarle paso a paso cómo imprimir elegantemente registros de enlace completo en el nodo

Cuando un usuario informa un problema: cuando se produce un error al utilizar una determinada función en línea, ¿cómo se puede localizar de forma rápida y precisa? ¿Cómo realizar un seguimiento eficaz de la optimización cuando una determinada interfaz de solicitud devuelve datos lentamente?

1. Principio y práctica

Como todos sabemos, cuando llega una solicitud, probablemente se generarán los siguientes registros:

1. AceesLog: registro de acceso de usuario

2. Excepción: registro de excepción de código

3. SQL: registro de consultas SQL

4. Tercero: tercero

de servicio de fiesta

¿Cómo realizar un seguimiento de todos los registros generados por una solicitud?

El enfoque general es utilizar un requestId como identificador único

y luego escribir un middleware para inyectar el requestId en el contexto. Cuando sea necesario realizar el registro, sáquelo del contexto para imprimirlo

en servicios de terceros y registros SQL

También es necesario inyectar el requestId en el contexto. El requestId se pasa a la función correspondiente para imprimir. Es demasiado problemático pasarlo capa por capa y el código también es relativamente intrusivo.

Nuestro objetivo es reducir la intrusión del código, inyectarlo una vez y rastrearlo automáticamente.

Después de la investigación, async_hooks puede rastrear el ciclo de vida del comportamiento asincrónico. En cada recurso asincrónico (cada solicitud es un recurso asincrónico), tiene 2 ID,

a saber, asyncId (el ID del ciclo de vida actual del recurso asincrónico) y trigerAsyncId (recurso asincrónico principal). IDENTIFICACIÓN).

async_hooks proporciona los siguientes enlaces de ciclo de vida para escuchar recursos asincrónicos:

asyncHook = async_hook.createHook({
  //Escuche la creación de recursos asincrónicos init(asyncId,type,triggerAsyncId,resource){},
  // Antes de que la función de devolución de llamada de recursos asíncronos comience a ejecutarse before(asyncId){},
  // Después de que la función de devolución de llamada de recursos asincrónica comience a ejecutarse, after(asyncId){},
  // Monitorear la destrucción de recursos asincrónicos destroy(asyncId){}
})

Luego, si hacemos un mapeo, cada asyncId se asigna a un almacenamiento y el requestId correspondiente se almacena en el almacenamiento, entonces el requestId se puede obtener fácilmente.

Da la casualidad de que la biblioteca cls-hook se ha encapsulado en función de async_hooks, manteniendo una copia de los datos en el mismo recurso asincrónico y almacenándola en forma de pares clave-valor. (Nota: async_hooked debe usarse en una versión superior de node>=8.2.1) Por supuesto, existen otras implementaciones en la comunidad, como cls-session, node-continuation-local-storage, etc.

Hablemos de un ejemplo del uso de cls-hooked en mi proyecto:

/session.js Crear un espacio de almacenamiento con nombre

const createNamespace = require('cls-hooked').createNamespace 
sesión constante = createNamespace('requestId-store') 
module.exports = sesión

/logger.js imprimir registro

const sesión = require('./session') 
módulo.exportaciones = { 
información: (mensaje) => 
{ 
const requestId = session.get('solicitudId')
console.log(`requestId:${requestId}`, mensaje) 
}, 
error: (mensaje) => 
{ 
const requestId = session.get('solicitudId') 
console.error(`requestId:${requestId}`, mensaje) 
} 
}

/sequelize.js sql llama al registrador para imprimir registros

const logger = require("./logger") 
nuevoSequelize( 
registro: función (sql, costtime) { 
logger.error(`sql exe: ${sql} | costtime ${costtime} ms`); 
} )

/app.js Establezca requestId, configure requestId para devolver el encabezado de respuesta e imprimir el registro de acceso

const session = require('./session') 
registrador constante = requerir('./logger') 
función asíncrona accessHandler (ctx, siguiente) 
{ 
const requestId = ctx.header['x-request-id'] || uuid()
parámetros constantes = ctx.request.body? JSON.stringify(ctx.request.body): JSON.stringify(ctx.request.query)
//Establecer requestId session.run(() => { session.set('requestId', requestId)
logger.info(`url:${ctx.request.path}; params:${params}`) siguiente()
//Establece el encabezado de respuesta de devolución ctx.res.setHeader('X-Request-Id',requestId)
}) }

Veamos el registro cuando la ruta de una solicitud es /home?a=1:

Registro de acceso:
requestId:79f422a6-6151-4bfd-93ca-3c6f892fb9ac url:/home;params:{"a":"1"}

registro sql:
ID de solicitud: 79f422a6-6151-4bfd-93ca-3c6f892fb9ac sql exe:
Ejecutado (predeterminado): SELECT `id` FROM t_user

Puede ver que el ID de solicitud de registro de todo el enlace para la misma solicitud es el mismo. Si luego se envía una alarma a la plataforma de alarmas, podemos encontrar el enlace completo ejecutado por esta solicitud según el requestId.

Los estudiantes atentos pueden notar que también configuré el requestId en el encabezado de respuesta devuelto por la interfaz. El propósito es que si se descubre que una solicitud responde lentamente o tiene problemas, el requestId se puede conocer directamente desde el navegador y analizar.

2. Gastos generales de rendimiento:

hice una prueba de esfuerzo localmente.

Esta es la comparación del uso de memoria:

Aproximadamente un 10% más que no usar async_hook.

Está bien para nuestro sistema QPS con sistema de 100 niveles, pero si es un servicio altamente concurrente, es posible que debamos considerarlo detenidamente.

PD: Si hay algún error, indíquelo. Si no le gustan, no comente.