DBLOG: sqlite Another operation is in progress - resync at NextSync

[Hadl]

Hallo, ich nutze dblog mit einer mittlerweile großen sqlite Datenbank.

Code Auswählen Erweitern

defmod logdb DbLog ./db.conf .*:.*
attr logdb DbLogType Current/History
attr logdb asyncMode 1
attr logdb cacheLimit 1000
attr logdb cacheOverflowThreshold 20000
attr logdb event-min-interval .*:3600
attr logdb event-on-change-reading .*
attr logdb room Log
attr logdb showproctime 1
attr logdb syncInterval 120
Das funktioniert meistens super, aber manchmal hängt sich das dblog auf und schreibt nichtsmehr in die Datenbank, bisher half dann nur ein fhem neustart. (Problem 1)
dblog ist dabei auf folgenden Status:

sqlite Another operation is in progress - resync at NextSync

Dabei werden dann die Daten beim Cache überlauf in ein Cache file geschrieben, welches dann aber (scheinbar) sofort wieder mit ner Null Byte Datei überschrieben wird. (Problem 2)

2026.03.17 14:13:33 2: logdb - WARNING - Cache is exported to file instead of logging it to database
2026.03.17 14:13:33 3: logdb - 20412 Cache rows exported to ./log/cache_logdb_2026-03-17_14-13-33
2026.03.17 14:13:33 3: logdb - Cache purged after exporting rows to ./log/cache_logdb_2026-03-17_14-13-33.
2026.03.17 14:13:33 2: logdb - WARNING - Cache is exported to file instead of logging it to database
2026.03.17 14:13:33 3: logdb - 0 Cache rows exported to ./log/cache_logdb_2026-03-17_14-13-33
2026.03.17 14:13:33 3: logdb - Cache purged after exporting rows to ./log/cache_logdb_2026-03-17_14-13-33.

Beim Versuch des Imports - der 0 Byte Datei - kommen dann natürlich keine Datensätze raus.
STATE: importCachefile finished, 0 datasets were imported

Das System ist ein Rpi 5 mit einer 1TB M.2 SSD

Hat jemand eine Idee was das sein könnte, oder wie ich das Problem weiter untersuchen könnte?

Vielen Dank

Hadl

[DS_Starter]

Hallo Hadl,

ich gehe ganz stark davon aus, dass deine DB zu langsam ist um die anfallende Datenmenge im Block zu verarbeiten.
Schau dir das Reading sql_processing_time an. Normalerweise liegt das im ms Bereich (0.0866 s bei mir (MariaDB)).

Wahrscheinlich ist die Zeit bei dir sehr hoch und der Schreibprozess ist noch nicht fertig wenn der nächste starten will.
Möglicherweise hilft es dir auf synchron umzustellen um jeden Event sofort wegzuschreiben oder eine Einstellung des attr insertMode.

Aber das grundlegende Problem wird die DB-Zeit sein. Dort müsstest du ansetzen.

Grüße,
Heiko

[Hadl]

Hallo Heiko,
ja, über den Zeiten bin ich natürlich drüber, weil ich immer 1000 Einträge auf einmal schreibe.
Damit hab ich ne sql_processing_time von 1.0-1.8s
Das ging für mich so in Ordnung, denn das passiert ja nur alle ca. 2 Minuten einmal.

In Summe war das deutlich effizienter als jedes mal wegen ein paar Daten die ganze Datenbank inkl. Index Tabelle neu schreiben zu müssen.

Wenn aber das Problem auftritt dann steigt der Cache bis 20000 Elemente an was immer mindestens 40 Minuten dauert.
Dann wird der Cache geschrieben (mit Problem 2), aber die Datenbank bleibt blockiert.
Über mehrere Stunden wird so nichts in die DB geschrieben, bis ich fhem neu starte.

Syncron hatte ich am Anfang als Einstellung, das wurde dann aber schnell zu langsam und hat mir zusätzlich die damals noch verwendete SD Karte schnell über den Jordan gebracht. (Asche auf mein Haupt, ich weis ja das man das nicht macht, aber nur Versuch macht klug )

insertMode als Array hört sich für mich richtig an, um nur einmal alle paar Minuten den Index schreiben zu müssen und nicht wegen jedem Eintrag extra. OK die SSD sollte nun mehr aushalten, aber kann das wirklich ne Verbesserung bewirken?

Was vermutest du, das die Blockade ist, warum über Stunden der Status "Another operation is in progress - resync at NextSync" besteht?

Hadl

[DS_Starter]

insertMode als Array hört sich für mich richtig an, um nur einmal alle paar Minuten den Index schreiben zu müssen und nicht wegen jedem Eintrag extra. OK die SSD sollte nun mehr aushalten, aber kann das wirklich ne Verbesserung bewirken?

Ausprobieren ...

Was vermutest du, das die Blockade ist, warum über Stunden der Status "Another operation is in progress - resync at NextSync" besteht?

Ich vermute es gibt bei dir Situationen gibt wo die Reaktionszeit/Schreibgeschwindigkeit derart schlecht ist, dass die ersten 1000  Einträge noch nicht geschrieben sind wenn die nächsten aus dem Cache in die DB sollen. Der Cache baut sich evtl. auf 1500 auf die dann im Block in die DB sollen was dann noch länger dauert.
Und so kann sich die Sutuation aufschaukeln bis es zum Überlauf kommt. Wie gesagt ... Theorie.

Du kannst dir sql_processing_time und CacheUsage in ein Filelog! loggen und kannst so vllt. über die Laufzeit einen Überblick erhalten wie sich die Situation entwickelt. Es gibt auch die Möglichkeit über attr SQLiteCacheSize bedingt Einfluß auf die Performance zu nehmen, genug RAM vorausgesetzt.

[Hadl]

Hallo Heiko,
ich hab nun gemessen ohne dem Attribut "insertMode", mit insertMode=0 und insertMode=1
Die Messwerte von background_processing_time und sql_processing_time bewegen sich beide immer im Bereich zwischen 1.0s und 1.8s
Einen update dieser Werte und damit warscheinlich ein echtes Schreiben bekomme ich ca. alle 90-120s
Das ganze sieht sehr stabil aus und ich sehe keine Ausreiser.

Da sollte eigentlich auch genug "Luft" sein mal die doppelte Menge schreiben zu können. Mit der Performance bin ich so zufrieden.
Als es blockiert hatte habe ich auch weder eine hohe CPU Last, noch eine hohe SSD Last feststellen können.

Ich hab mir mal ein Filelog dafür erstellen lassen, aber scheinbar kommen da nur beim Schreiben Events. Damit ist CacheUsage immer fast leer, obwohl ich beobachtet hatte das das Schreiben aufgrund von mehr als 1000 Einträgen erfolgt ist.

2026-03-19_12:38:42 logdb background_processing_time: 1.8071
2026-03-19_12:38:42 logdb sql_processing_time: 1.7977
2026-03-19_12:38:42 logdb CacheUsage: 2

Der Fehler tritt auch selten auf und ich weiß nicht wie ich ihn provozieren kann.

[Hadl]

Hallo,
heute ist der Fehler mal wieder aufgetreten.

Code Auswählen Erweitern

define logdb DbLog ./db.conf .*:.*
attr logdb DbLogType Current/History
attr logdb asyncMode 1
attr logdb cacheLimit 1000
attr logdb cacheOverflowThreshold 20000
attr logdb event-min-interval .*:3600
attr logdb event-on-change-reading .*
attr logdb exportCacheAppend 1
attr logdb insertMode 0
attr logdb room Log
attr logdb showproctime 1
attr logdb syncInterval 120
#   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
#   CONFIGURATION ./db.conf
#   DEF        ./db.conf .*:.*
#   FD         5
#   FUUID      5d6c1e06-f33f-a72e-296f-6c78ab79b33a837c
#   FVERSION   93_DbLog.pm:v5.11.0-s29401/2024-12-05
#   MODE       asynchronous
#   MODEL      SQLITE
#   NAME       logdb
#   NR         2
#   NTFY_ORDER 50-logdb
#   PID        833
#   REGEXP     .*:.*
#   SBP_PID    972
#   SBP_STATE  running
#   STATE      Another operation is in progress - resync at NextSync
#   TYPE       DbLog
#   dbconn     SQLite:dbname=/opt/fhem/fhem.db
#   dbuser     
#   eventCount 34366
#   HELPER:
#     COLSET     1
#     DEVICECOL  64
#     EVENTCOL   512
#     LASTLIMITRUNTIME 1778345398.72136
#     LONGRUN_PID 1778329921.99097
#     OLDSTATE   Another operation is in progress - resync at NextSync
#     PACKAGE    main
#     READINGCOL 64
#     TC         current
#     TH         history
#     TYPECOL    64
#     UNITCOL    32
#     VALUECOL   128
#     VERSION    5.11.0
#   Helper:
#     DBLOG:
#       CacheOverflowLastNum:
#         logdb:
#           TIME       1778344311.10306
#           VALUE      0
#       CacheOverflowLastState:
#         logdb:
#           TIME       1778344311.10306
#           VALUE      normal
#       CacheUsage:
#         logdb:
#           TIME       1778344250.435
#           VALUE      0
#       background_processing_time:
#         logdb:
#           TIME       1778329857.84606
#           VALUE      1.9819
#       lastCachefile:
#         logdb:
#           TIME       1778344250.43319
#           VALUE      ./log/cache_logdb_2025-05-18_07-14-14 (0 cache rows exported)
#       sql_processing_time:
#         logdb:
#           TIME       1778329857.84606
#           VALUE      1.9718
#       state:
#         logdb:
#           TIME       1778344250.43776
#           VALUE      Another operation is in progress - resync at NextSync
#   OLDREADINGS:
#   READINGS:
#     2026-05-09 18:49:58   CacheOverflowLastNum 0
#     2026-05-09 18:31:51   CacheOverflowLastState normal
#     2026-05-09 18:50:56   CacheUsage      17374
#     2026-05-09 18:49:58   NextSync        2026-05-09 18:51:58 or when CacheUsage 1000 is reached
#     2026-05-09 14:30:57   background_processing_time 1.9819
#     2026-05-09 18:30:50   lastCachefile   ./log/cache_logdb_2025-05-18_07-14-14 (0 cache rows exported)
#     2026-05-09 14:30:57   sql_processing_time 1.9718
#     2026-05-09 18:49:58   state           Another operation is in progress - resync at NextSync
#
setstate logdb Another operation is in progress - resync at NextSync
setstate logdb 2026-05-09 18:49:58 CacheOverflowLastNum 0
setstate logdb 2026-05-09 18:31:51 CacheOverflowLastState normal
setstate logdb 2026-05-09 18:50:56 CacheUsage 17374
setstate logdb 2026-05-09 18:49:58 NextSync 2026-05-09 18:51:58 or when CacheUsage 1000 is reached
setstate logdb 2026-05-09 14:30:57 background_processing_time 1.9819
setstate logdb 2026-05-09 18:30:50 lastCachefile ./log/cache_logdb_2025-05-18_07-14-14 (0 cache rows exported)
setstate logdb 2026-05-09 14:30:57 sql_processing_time 1.9718
setstate logdb 2026-05-09 18:49:58 state Another operation is in progress - resync at NextSync

Ich habe nun auch einen Filelog vom dblog mitlaufen lassen, dort sieht man das es ab 14:33 zu dem Problem "Another operation is in progress - resync at NextSync" kam. Seitdem wurde auch "sql_processing_time" nichtmehr geschrieben. Vorher war es stabil unter 2 Sekunden und wurde alle 1-2 Minuten geschrieben.
Über mehrere Stunden hat sich das nicht automatisch geheilt. Nach einen fhem restart gehts aber wieder normal!
Die meisten Cache files sind auch leer, weil sie nachdem sie geschrieben wurden gleich wieder mit "0 cache rows exported" überschrieben wurden.

Code Auswählen Erweitern

2026-05-09_14:30:57 logdb background_processing_time: 1.9819
2026-05-09_14:30:57 logdb sql_processing_time: 1.9718
2026-05-09_14:30:57 logdb CacheUsage: 123
2026-05-09_14:33:02 logdb Another operation is in progress - resync at NextSync
2026-05-09_14:33:02 logdb CacheUsage: 1060
2026-05-09_14:55:06 logdb CacheOverflowLastNum: 723
2026-05-09_14:55:06 logdb CacheOverflowLastState: exceeded
2026-05-09_14:55:06 logdb CacheUsage: 20725
2026-05-09_14:55:06 logdb CacheOverflowLastNum: 725
2026-05-09_14:55:06 logdb lastCachefile: ./log/cache_logdb_2025-05-18_07-14-14 (20725 cache rows exported)
2026-05-09_14:55:06 logdb CacheUsage: 0
2026-05-09_14:55:06 logdb Cache exported to "lastCachefile" due to Cache overflow
2026-05-09_14:55:06 logdb Another operation is in progress - resync at NextSync
2026-05-09_14:55:06 logdb lastCachefile: ./log/cache_logdb_2025-05-18_07-14-14 (0 cache rows exported)
2026-05-09_14:55:06 logdb CacheUsage: 1
2026-05-09_14:55:06 logdb CacheUsage: 0
2026-05-09_14:55:06 logdb CacheUsage: 1
2026-05-09_14:55:06 logdb Cache exported to "lastCachefile" due to Cache overflow
2026-05-09_14:55:06 logdb CacheUsage: 2
2026-05-09_14:55:06 logdb Another operation is in progress - resync at NextSync
2026-05-09_14:55:06 logdb CacheUsage: 3
2026-05-09_14:56:06 logdb CacheOverflowLastNum: 0
2026-05-09_14:56:06 logdb CacheOverflowLastState: normal
2026-05-09_14:56:06 logdb CacheUsage: 1069
2026-05-09_15:17:08 logdb CacheOverflowLastNum: 645
2026-05-09_15:17:08 logdb CacheOverflowLastState: exceeded
2026-05-09_15:17:08 logdb CacheUsage: 20647
2026-05-09_15:17:08 logdb CacheOverflowLastNum: 647
2026-05-09_15:17:08 logdb lastCachefile: ./log/cache_logdb_2025-05-18_07-14-14 (20647 cache rows exported)
2026-05-09_15:17:08 logdb CacheUsage: 0
2026-05-09_15:17:08 logdb Cache exported to "lastCachefile" due to Cache overflow
2026-05-09_15:17:08 logdb Another operation is in progress - resync at NextSync
2026-05-09_15:17:08 logdb lastCachefile: ./log/cache_logdb_2025-05-18_07-14-14 (0 cache rows exported)
2026-05-09_15:17:08 logdb CacheUsage: 1
2026-05-09_15:17:08 logdb CacheUsage: 0
2026-05-09_15:17:08 logdb CacheUsage: 1
2026-05-09_15:17:08 logdb Cache exported to "lastCachefile" due to Cache overflow
2026-05-09_15:17:08 logdb CacheUsage: 2
2026-05-09_15:17:08 logdb Another operation is in progress - resync at NextSync
2026-05-09_15:17:08 logdb CacheUsage: 3
Die Datenbank kann ich mit sqlite3 Kommandos von der Konsole aus nutzen, da scheint nichts zu blockieren.

Hat jemand eine Idee woran das liegen könnte?

Viele Grüße

Hadl