- VERSION 5.09.16.2

- feat(logs): Implementación de Cacheo y Escritura Transaccional en Lotes

- Implementa la funcionalidad de cacheo de logs en memoria y escritura transaccional para reducir el overhead de E/S de disco en SQLite [1, 2].

- Cambios principales:
		1. Refactorización de LogQueryPerformance y LogServerError para que solo almacenen logs en las cachés globales (QueryLogCache y ErrorLogCache) [3].
		2. Introducción de WriteQueryLogsBatch y WriteErrorLogsBatch, que vacían las cachés y realizan la inserción a SQLite dentro de una única transacción atómica (`BeginTransaction`/`TransactionSuccessful`), disparada por umbral (`LOG_CACHE_THRESHOLD`) o periódicamente por `TimerLogs_Tick` [4-7].
		3. Corrección del manejo de objetos List en las rutinas de lote (Write*LogsBatch): Se implementó la copia explícita de contenido (`List.AddAll`) dentro del bloqueo (`MainConnectorsLock`) para asegurar que el lote mantenga sus registros, resolviendo el problema de tamaño cero causado por la asignación de referencias.
This commit is contained in:
2025-09-19 18:43:47 -06:00
parent dbfafbf9ac
commit 884cb96f9d
8 changed files with 347 additions and 59 deletions

View File

@@ -55,7 +55,7 @@ Version=10.3
#CommandLineArgs:
#MergeLibraries: True
' VERSION 5.09.16
' VERSION 5.09.16.2
'###########################################################################################################
'###################### PULL #############################################################
'Ctrl + click ide://run?file=%WINDIR%\System32\cmd.exe&Args=/c&Args=git&Args=pull
@@ -112,6 +112,7 @@ Sub Process_Globals
' NUEVAS VARIABLES para control granular de logs
' Mapa para almacenar el estado de logging (True/False) por cada DBKey (DB1, DB2, etc.).
Public SQLiteLoggingStatusByDB As Map
' Bandera global que indica si AL MENOS una base de datos tiene los logs habilitados.
Public IsAnySQLiteLoggingEnabled As Boolean
@@ -121,12 +122,25 @@ Sub Process_Globals
ErrorMessage As String, _
ParamsToExecute As List _ ' La lista de parámetros final a usar en la ejecución SQL
)
Public QueryLogCache As List ' Cache para los logs de rendimiento (query_logs)
Public ErrorLogCache As List ' Cache para los logs de errores y advertencias
Public Const LOG_CACHE_THRESHOLD As Int = 10 ' Umbral de registros para forzar la escritura
Dim logger As Boolean
End Sub
Sub AppStart (Args() As String)
#if DEBUG
logger = True
#else
logger = False
#End If
' --- Subrutina principal que se ejecuta al iniciar la aplicación ---
bc.Initialize("BC")
QueryLogCache.Initialize
ErrorLogCache.Initialize
' 1. Inicializa la base de datos local de usuarios (SQLite) y la tabla de logs.
InitializeSQLiteDatabase
@@ -276,10 +290,10 @@ Sub AppStart (Args() As String)
If IsAnySQLiteLoggingEnabled Then
timerLogs.Enabled = True
Log("Main.AppStart: Timer de limpieza de logs ACTIVADO (al menos una DB requiere logs).")
If logger Then Log("Main.AppStart: Timer de limpieza de logs ACTIVADO (al menos una DB requiere logs).")
Else
timerLogs.Enabled = False
Log("Main.AppStart: Timer de limpieza de logs DESHABILITADO (ninguna DB requiere logs).")
If logger Then Log("Main.AppStart: Timer de limpieza de logs DESHABILITADO (ninguna DB requiere logs).")
End If
' <<<< Fin del bloque del Timer >>>>
@@ -321,7 +335,7 @@ Sub InitializeSQLiteDatabase
SQL1.ExecNonQuery(createUserTable)
' Crear tabla 'query_logs'
Log("Creando tabla 'query_logs' con columnas de rendimiento.")
If logger Then Log("Creando tabla 'query_logs' con columnas de rendimiento.")
Dim createQueryLogsTable As String = "CREATE TABLE query_logs (id INTEGER PRIMARY KEY AUTOINCREMENT, query_name TEXT, duration_ms INTEGER, timestamp INTEGER, db_key TEXT, client_ip TEXT, busy_connections INTEGER, handler_active_requests INTEGER)"
SQL1.ExecNonQuery(createQueryLogsTable)
@@ -342,11 +356,11 @@ Sub InitializeSQLiteDatabase
Log("Base de datos de usuarios cargada.")
' >>> INICIO: Lógica de migración (ALTER TABLE) si la DB ya existía <<<
Log("Verificando y migrando tabla 'query_logs' si es necesario.")
If logger Then Log("Verificando y migrando tabla 'query_logs' si es necesario.")
If SQL1.ExecQuerySingleResult("SELECT name FROM sqlite_master WHERE type='table' AND name='query_logs'") = Null Then
Log("Tabla 'query_logs' no encontrada, creándola con columnas de rendimiento.")
If logger Then Log("Tabla 'query_logs' no encontrada, creándola con columnas de rendimiento.")
Dim createQueryLogsTable As String = "CREATE TABLE query_logs (id INTEGER PRIMARY KEY AUTOINCREMENT, query_name TEXT, duration_ms INTEGER, timestamp INTEGER, db_key TEXT, client_ip TEXT, busy_connections INTEGER, handler_active_requests INTEGER)"
@@ -371,7 +385,7 @@ Sub InitializeSQLiteDatabase
rs.Close
If columnExists = False Then
Log("Añadiendo columna 'busy_connections' a query_logs.")
If logger Then Log("Añadiendo columna 'busy_connections' a query_logs.")
SQL1.ExecNonQuery("ALTER TABLE query_logs ADD COLUMN busy_connections INTEGER DEFAULT 0")
End If
@@ -388,20 +402,34 @@ Sub InitializeSQLiteDatabase
rs.Close
If columnExists = False Then
Log("Añadiendo columna 'handler_active_requests' a query_logs.")
If logger Then Log("Añadiendo columna 'handler_active_requests' a query_logs.")
SQL1.ExecNonQuery("ALTER TABLE query_logs ADD COLUMN handler_active_requests INTEGER DEFAULT 0")
End If
columnExists = False
rs = SQL1.ExecQuery("PRAGMA table_info(query_logs)")
Do While rs.NextRow
If rs.GetString("name").EqualsIgnoreCase("timestamp_text_local") Then
columnExists = True
Exit ' La columna ya existe, salimos del bucle.
End If
Loop
rs.Close
If columnExists = False Then
If logger Then Log("Añadiendo columna 'timestamp_text_local' a query_logs.")
' Usamos 'TEXT' para almacenar la cadena de fecha/hora formateada.
SQL1.ExecNonQuery("ALTER TABLE query_logs ADD COLUMN timestamp_text_local TEXT")
End If
' >>> INICIO: Lógica de migración para 'errores' si la DB ya existía <<<
Log("Verificando y migrando tabla 'errores' si es necesario.")
If logger Then Log("Verificando y migrando tabla 'errores' si es necesario.")
If SQL1.ExecQuerySingleResult("SELECT name FROM sqlite_master WHERE type='table' AND name='errores'") = Null Then
Log("Tabla 'errores' no encontrada, creándola.")
If logger Then Log("Tabla 'errores' no encontrada, creándola.")
Dim createErrorsTable As String = "CREATE TABLE errores (id INTEGER PRIMARY KEY AUTOINCREMENT, timestamp INTEGER, type TEXT, source TEXT, message TEXT, db_key TEXT, command_name TEXT, client_ip TEXT)"
SQL1.ExecNonQuery(createErrorsTable)
Else
Log("Tabla 'errores' ya existe.")
If logger Then Log("Tabla 'errores' ya existe.")
End If
' >>> FIN: Lógica de migración para 'errores' <<<
@@ -411,45 +439,155 @@ Sub InitializeSQLiteDatabase
End If
End Sub
' --- Subrutina para registrar las métricas de rendimiento de las queries en la tabla 'query_logs'. ---
' ¡MODIFICADA PARA USAR FILTRADO GRANULAR POR DBKEY!
Public Sub LogQueryPerformance(QueryName As String, DurationMs As Long, DbKey As String, ClientIp As String, HandlerActiveRequests As Int, PoolBusyConnections As Int)
' Obtener el estado de logging para esta DBKey. Usar False si la DBKey no existe en el mapa.
Dim isEnabled As Boolean = SQLiteLoggingStatusByDB.GetDefault(DbKey, False)
If isEnabled Then
Try
SQL1.ExecNonQuery2("INSERT INTO query_logs (query_name, duration_ms, timestamp, db_key, client_ip, busy_connections, handler_active_requests) VALUES (?, ?, ?, ?, ?, ?, ?)", _
Array As Object(QueryName, DurationMs, DateTime.Now, DbKey, ClientIp, PoolBusyConnections, HandlerActiveRequests))
Catch
Log("Error al guardar log de query en SQLite (Main.LogQueryPerformance): " & LastException.Message)
End Try
' Formato de tiempo necesario para la columna timestamp_text_local
DateTime.DateFormat = "yyyy-MM-dd HH:mm:ss.SSS"
Dim formattedTimestamp As String = DateTime.Date(DateTime.Now)
' 1. Crear el mapa de datos (log entry)
Dim logEntry As Map = CreateMap("query_name": QueryName, "duration_ms": DurationMs, "timestamp": DateTime.Now, _
"db_key": DbKey, "client_ip": ClientIp, "busy_connections": PoolBusyConnections, _
"handler_active_requests": HandlerActiveRequests, "timestamp_text_local": formattedTimestamp)
' 2. Zona Crítica: Añadir a la caché y verificar el umbral
Dim shouldWriteBatch As Boolean = False
' Usamos el lock global para garantizar que la adición y la verificación del tamaño sean atómicas.
MainConnectorsLock.RunMethod("lock", Null)
QueryLogCache.Add(logEntry)
If QueryLogCache.Size >= LOG_CACHE_THRESHOLD Then
shouldWriteBatch = True
End If
MainConnectorsLock.RunMethod("unlock", Null)
' 3. Si se alcanzó el umbral, disparamos la escritura.
' NO DEBE HACERSE CON EL LOCK PUESTO.
If shouldWriteBatch Then
CallSub(Me, "WriteQueryLogsBatch")
End If
End If
End Sub
' --- Subrutina para registrar errores y advertencias en la tabla 'errores'. ---
' ¡MODIFICADA PARA USAR FILTRADO GRANULAR POR DBKEY!
Public Sub LogServerError(Type0 As String, Source As String, Message As String, DBKey As String, CommandName As String, ClientIp As String)
' Obtener el estado de logging para esta DBKey. Usar False si la DBKey es Null o no está en el mapa.
Dim isEnabled As Boolean = SQLiteLoggingStatusByDB.GetDefault(DBKey, False)
If isEnabled Then
Try
SQL1.ExecNonQuery2("INSERT INTO errores (timestamp, type, source, message, db_key, command_name, client_ip) VALUES (?, ?, ?, ?, ?, ?, ?)", _
Array As Object(DateTime.Now, Type0, Source, Message, DBKey, CommandName, ClientIp))
Catch
Log("ERROR CRÍTICO: Fallo al guardar el log de error/advertencia en SQLite (Main.LogServerError): " & LastException.Message)
End Try
' Log($"[DEBUG CACHE] Se recibió log de error/advertencia para: ${CommandName}"$) '<--- Nuevo Log 1
Dim logEntry As Map = CreateMap("timestamp": DateTime.Now, "type": Type0, "source": Source, "message": Message, _
"db_key": DBKey, "command_name": CommandName, "client_ip": ClientIp)
Dim shouldWriteBatch As Boolean = False
' 1. Zona Crítica: Añadir a la caché y verificar el umbral
' Usamos el lock para Thread Safety
MainConnectorsLock.RunMethod("lock", Null)
' Log($"[DEBUG CACHE] Lock adquirido. Tamaño actual de ErrorLogCache: ${ErrorLogCache.Size}"$) '<--- Nuevo Log 2
ErrorLogCache.Add(logEntry)
' Log($"[DEBUG CACHE] Log añadido. Nuevo tamaño: ${ErrorLogCache.Size}. Umbral: ${LOG_CACHE_THRESHOLD}"$) '<--- Nuevo Log 3
If ErrorLogCache.Size >= LOG_CACHE_THRESHOLD Then
shouldWriteBatch = True
' Log(">>> [DEBUG CACHE] UMBRAL ALCANZADO. DISPARANDO ESCRITURA BATCH. <<<") '<--- Nuevo Log 4
End If
MainConnectorsLock.RunMethod("unlock", Null)
' Log($"[DEBUG CACHE] Lock liberado."$) '<--- Nuevo Log 5
' 2. Si se alcanzó el umbral (o si el timer lo llama), disparamos la escritura.
If shouldWriteBatch Then
CallSub(Me, "WriteErrorLogsBatch")
End If
Else
' Log($"[DEBUG CACHE] Logging deshabilitado para DBKey: ${DBKey}. Log de error omitido."$)
End If
End Sub
Public Sub WriteQueryLogsBatch
Dim logsToWrite As List
logsToWrite.Initialize ' 1. Inicializar la lista local (CRÍTICO)
' === PASO 1: Intercambio Atómico de Caché (Protegido por ReentrantLock) ===
MainConnectorsLock.RunMethod("lock", Null)
If QueryLogCache.Size = 0 Then
MainConnectorsLock.RunMethod("unlock", Null)
' Log("[DEBUG BATCH-Q] Saliendo: Caché de rendimiento vacía.")
Return
End If
' *** CORRECCIÓN CRÍTICA: Copia de contenido (AddAll) en lugar de referencia. ***
logsToWrite.AddAll(QueryLogCache)
Dim batchSize As Int = logsToWrite.Size
' Vaciamos la caché global. logsToWrite ahora contiene la copia de los elementos.
QueryLogCache.Initialize
MainConnectorsLock.RunMethod("unlock", Null)
If logger Then Log($"[LOG BATCH] Iniciando escritura transaccional de ${batchSize} logs de rendimiento. Logs copiados: ${logsToWrite.Size}"$)
' === PASO 2: Escritura Transaccional a SQLite ===
Try
' 1. Iniciar la transacción: Todo lo que siga es una única operación de disco.
SQL1.BeginTransaction
For Each logEntry As Map In logsToWrite
SQL1.ExecNonQuery2("INSERT INTO query_logs (query_name, duration_ms, timestamp, db_key, client_ip, busy_connections, handler_active_requests, timestamp_text_local) VALUES (?, ?, ?, ?, ?, ?, ?, ?)", _
Array As Object(logEntry.Get("query_name"), logEntry.Get("duration_ms"), logEntry.Get("timestamp"), logEntry.Get("db_key"), _
logEntry.Get("client_ip"), logEntry.Get("busy_connections"), logEntry.Get("handler_active_requests"), _
logEntry.Get("timestamp_text_local")))
Next
' 2. Finalizar la transacción: Escritura eficiente a disco.
SQL1.TransactionSuccessful
if logger then Log($"[LOG BATCH] Lote de ${batchSize} logs de rendimiento escrito exitosamente."$)
Catch
' Si falla, deshacemos todos los logs del lote y registramos el fallo.
SQL1.Rollback
Dim ErrorMsg As String = "ERROR CRÍTICO: Fallo al escribir lote de logs de rendimiento en SQLite: " & LastException.Message
Log(ErrorMsg)
' Usamos LogServerError para que el fallo quede registrado en la tabla 'errores' si el logging está habilitado.
LogServerError("ERROR", "Main.WriteQueryLogsBatch", ErrorMsg, Null, "log_batch_write_performance", Null)
End Try
End Sub
' --- Subrutina de evento para el Timer 'timerLogs'. ---
' El estado 'Enabled' del Timer ya está controlado por IsAnySQLiteLoggingEnabled en AppStart y Manager.
Sub TimerLogs_Tick
Try
' 1. Vaciado de logs de rendimiento (asumiendo que WriteQueryLogsBatch también fue implementado)
WriteQueryLogsBatch
' 2. Vaciado de logs de errores
WriteErrorLogsBatch
' 3. Limpieza y VACUUM (esto ya verifica IsAnySQLiteLoggingEnabled [8])
borraArribaDe15000Logs
Catch
Dim ErrorMsg As String = "ERROR en TimerLogs_Tick al intentar borrar logs: " & LastException.Message
Log(ErrorMsg)
@@ -457,16 +595,77 @@ Sub TimerLogs_Tick
End Try
End Sub
Public Sub WriteErrorLogsBatch
Dim logsToWrite As List
logsToWrite.Initialize ' *** Aseguramos que logsToWrite sea una LISTA NUEVA y no dependa de la referencia.
' === PASO 1: Intercambio Atómico de Caché (Protegido por ReentrantLock) ===
MainConnectorsLock.RunMethod("lock", Null) ' Adquirimos el bloqueo.
' Log($"[DEBUG BATCH] Lock adquirido en WriteErrorLogsBatch. Caché Size: ${ErrorLogCache.Size}"$)
If ErrorLogCache.Size = 0 Then
MainConnectorsLock.RunMethod("unlock", Null)
' Log("[DEBUG BATCH] Saliendo: Caché vacía.")
Return
End If
' *** CORRECCIÓN CRÍTICA: Copiamos el CONTENIDO de forma atómica. ***
logsToWrite.AddAll(ErrorLogCache) ' <--- ESTO PASA LOS 10 REGISTROS A LA NUEVA LISTA
' Vaciamos la caché global. logsToWrite AHORA ES INDEPENDIENTE.
ErrorLogCache.Initialize
MainConnectorsLock.RunMethod("unlock", Null) ' Liberamos el bloqueo.
' Usamos el tamaño de la lista *copiada*.
Dim batchSize As Int = logsToWrite.Size
If logger Then Log($"[LOG BATCH] Iniciando escritura transaccional de ${batchSize} logs de ERRORES a SQLite. Logs copiados: ${logsToWrite.Size}"$)
' === PASO 2: Escritura Transaccional a SQLite (Usa logsToWrite) ===
If batchSize = 0 Then
Log("ADVERTENCIA: Fallo en la copia de la lista. logsToWrite está vacía. Abortando escritura.")
Return
End If
Try
' 1. Iniciar la transacción.
SQL1.BeginTransaction
For Each logEntry As Map In logsToWrite
' ... (Tu lógica de SQL1.ExecNonQuery2 aquí) ...
SQL1.ExecNonQuery2("INSERT INTO errores (timestamp, type, source, message, db_key, command_name, client_ip) VALUES (?, ?, ?, ?, ?, ?, ?)", _
Array As Object(logEntry.Get("timestamp"), logEntry.Get("type"), logEntry.Get("source"), logEntry.Get("message"), _
logEntry.Get("db_key"), logEntry.Get("command_name"), logEntry.Get("client_ip")))
Next
' 2. Confirmar la transacción.
SQL1.TransactionSuccessful
If logger Then Log($"[LOG BATCH] Lote de ${logsToWrite.Size} logs de ERRORES escrito exitosamente."$)
Catch
' 3. Rollback si falla.
SQL1.Rollback
Dim ErrorMsg As String = "ERROR CRÍTICO: Fallo al escribir lote de logs de ERRORES en SQLite: " & LastException.Message
Log(ErrorMsg)
End Try
End Sub
' --- Borra los registros más antiguos de la tabla 'query_logs' y hace VACUUM. ---
' ¡MODIFICADA PARA USAR FILTRADO GLOBAL!
Sub borraArribaDe15000Logs 'ignore
If IsAnySQLiteLoggingEnabled Then ' Solo ejecutar si al menos una DB requiere logs.
Log("Recortando la tabla de 'query_logs', límite de 15,000 registros.")
If logger Then Log("Recortando la tabla de 'query_logs', límite de 15,000 registros.")
SQL1.ExecNonQuery("DELETE FROM query_logs WHERE timestamp NOT in (SELECT timestamp FROM query_logs ORDER BY timestamp desc LIMIT 15000 )")
SQL1.ExecNonQuery("vacuum;")
Else
' Si IsAnySQLiteLoggingEnabled es False, el Timer no debería estar activo.
Log("AVISO: Tarea de limpieza de logs omitida. El logging global de SQLite está deshabilitado.")
If logger Then Log("AVISO: Tarea de limpieza de logs omitida. El logging global de SQLite está deshabilitado.")
End If
End Sub