Freeze during Z2M device update

Hello everyone,

THIS IS A CRY FOR HELP XD

I’m trying to update my devices, but some Gladys instances freeze, I suppose because they have a lot of states.
I need to buy two NVMe SSDs for my NAS at the end of the year to improve my RAM (prices are so high now :eyes:)

  • What can I do in the meantime?
  • What should I look for in the logs to check if Gladys is stuck or if it’s working?

Thanks in advance (in the meantime, my home automation is down :smiley:

Do you have easy access to the database? Are you ready to delete old states for these devices?
If so, we can guide you to run queries manually.

Otherwise, we can consider it a bug and improve the migration to be done in chunks or in the background.

Are you trying to update in the Gladys interface for z2m? To add a feature?

Yes, no problem with that :slight_smile:

I was trying to update my plug to add the energy consumption features from the Gladys interface in discovery then update

It would still be best not to delete :smiley:

I continued the diagnosis with ChatGPT, taking advantage of the fact that Gladys was still in the « freeze » state.

The problem occurs during the update/synchronization of a Zigbee2MQTT device from Gladys. In my case, it was a plug that was supposed to retrieve new features related to energy/consumption.

Several checks allowed us to rule out a few leads:

  • The Gladys container is not saturated: around 3% CPU and 2.4 GB of RAM out of 19 GB available during the freeze.
  • Zigbee2MQTT does not seem saturated either.
  • The Gladys Node process remains alive.
  • GET / on Gladys responds immediately with HTTP 200, so Express is still able to serve the static frontend.
  • On the other hand, calls to the dynamic API, for example retrieving devices via my proxy, end in timeout.
  • SQLite remains accessible from another process during the freeze: simple queries respond in about 0.5 seconds.
  • The SQLite WAL was about 1 GB, but PRAGMA wal_checkpoint(PASSIVE) returns 0|227|227, so no indication of a blocked checkpoint.
  • t_device_feature_state contains 0 rows (histories have been migrated to DuckDB) and t_device_feature only 446 rows.

With ChatGPT, we then directly inspected the code present in my Gladys container.

The Zigbee2MQTT getDiscoveredDevices.js part indeed contains the recent fixes regarding energy features: preservation of consumption/cost features, merge with the existing device, then call to addEnergyFeatures().

On the other hand, in my device.create.js, after updating a feature, I currently have:

await deviceFeature.update(featureToUpdate, { transaction });

if (deviceFeature.keep_history === false) {
  deviceFeaturesIdsToPurge.push(deviceFeature.id);
}

ChatGPT compared this behavior with the current Gladys code and identified a significant difference. The corrected code remembers the old value:

const keepHistoryBeforeUpdate = deviceFeature.keep_history;

await deviceFeature.update(featureToUpdate, { transaction });

if (
  keepHistoryBeforeUpdate !== false &&
  deviceFeature.keep_history === false
) {
  deviceFeaturesIdsToPurge.push(deviceFeature.id);
}

The difference is that in my version, each update of a device can request a purge for all features that already have keep_history=false, even if this value has not changed.

After the transaction, Gladys then emits:

this.eventManager.emit(
  EVENTS.DEVICE.PURGE_STATES_SINGLE_FEATURE,
  deviceFeatureIdToPurge
);

The current hypothesis proposed by ChatGPT is therefore that Z2M updates cause an accumulation of unnecessary purge tasks. These processes go through DuckDB and could accumulate until they make Gladys’ dynamic APIs unresponsive, while the Node process itself continues to function.

This hypothesis fits particularly well with the observed behavior: normal CPU/RAM + accessible static frontend + accessible SQLite + Gladys API that times out.

This isn’t the same integration, but it looks very strangely like what I had and opened as an Issue: Overkiz integration: assigning a room to a device takes several minutes (freezes the interface) · Issue #2900 · GladysAssistant/Gladys · GitHub

@pierre-gilles @cicoub13 small progress

Summary by chatGPT:

Complete freeze of Gladys when updating a Zigbee2MQTT device

I encounter a reproducible blockage of Gladys when updating a socket named Computer Station from the Zigbee2MQTT interface.

Originally, I simply wanted to update this device because some features related to energy/consumption were missing.

Symptoms

When updating the device from Gladys:

  • the request times out;

  • the interface becomes partially or completely unusable;

  • SQLite writes then start to fail with:

    SequelizeTimeoutError
    SQLITE_BUSY: database is locked

For example:

Unable to reset failure count of integration ...
SQLITE_BUSY: database is locked

The HTTP server itself continues to respond on port 8455.

DB Configuration

The SQLite database is quite large:

gladys-production.db        ~12 GB
gladys-production.db-wal   ~1 GB
gladys-production.duckdb   ~1.9 GB

SQLite is running in WAL mode:

PRAGMA journal_mode;
wal

A passive checkpoint works:

PRAGMA wal_checkpoint(PASSIVE);
0|227|227

Simple queries on SQLite remain fast:

SELECT COUNT(*) FROM t_device_feature;
446

real 0m0.090s

And:

SELECT COUNT(*) FROM t_device_feature_state;
0

The states therefore seem to have been successfully migrated to DuckDB.

Device concerned

The device is:

id:
fd928ba6-ca0d-4a0d-8483-5b74cfddce8c

external_id:
zigbee2mqtt:Computer Station

Before the update attempt, its recorded features include:

Switch
Consumed power
Consumed current
Average voltage
Consumed energy
Signal strength
Access control mode

The « Access control mode » feature corresponds to:

zigbee2mqtt:Computer Station:access-control:mode:child_lock

Investigation in device.create.js

I instrumented:

/src/server/lib/device/device.create.js

aiming to precisely determine where the transaction is blocked.

The beginning of the update works normally:

[DEBUG DEVICE CREATE] START zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE getDeviceInDb zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] AFTER getDeviceInDb zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE device update zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] AFTER device update zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE feature cleanup zigbee2mqtt:Computer Station

The blockage therefore occurs during this part of device.create.js:

await Promise.map(deviceInDb.features, async (existingFeature) => {
  if (!matchFeatureInList(existingFeature, features)) {
    await existingFeature.destroy({ transaction });
  }
});

I then instrumented each feature.

Result:

[DEBUG FEATURE CLEANUP] ...:switch:binary:state matched= true
[DEBUG FEATURE CLEANUP] ...:switch:power:power matched= true
[DEBUG FEATURE CLEANUP] ...:switch:current:current matched= true
[DEBUG FEATURE CLEANUP] ...:switch:voltage:voltage matched= true
[DEBUG FEATURE CLEANUP] ...:switch:energy:energy matched= true

Then:

[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:access-control:mode:child_lock matched= false
[DEBUG FEATURE DESTROY] BEFORE zigbee2mqtt:Computer Station:access-control:mode:child_lock

And no DEBUG FEATURE DESTROY AFTER appears.

The next feature is still inspected by the Promise.map:

[DEBUG FEATURE CLEANUP] ...:signal:integer:linkquality matched= true

but the Promise.map never completes because the destroy() of child_lock remains blocked.

What seems to be happening

The new definition returned by Zigbee2MQTT no longer contains the feature:

access-control:mode:child_lock

Gladys therefore logically considers this old feature as deleted and executes:

await existingFeature.destroy({ transaction });

It is precisely this call that does not return.

The device.create() transaction then remains open.

Shortly after, other components of Gladys try to write to SQLite and start producing:

SQLITE_BUSY: database is locked

For example, updates to t_service:

UPDATE `t_service`
SET `failure_count`=$1,`updated_at`=$2
WHERE `id` = $3

end in SequelizeTimeoutError.

This therefore gives, at this stage, the following sequence:

Z2M device update
    ↓
device.create()
    ↓
deviceInDb.update()                  OK
    ↓
cleanup of old features
    ↓
child_lock absent from new device
    ↓
existingFeature.destroy({transaction})
    ↓
BLOCKAGE
    ↓
SQLite transaction remaining open
    ↓
other writes
    ↓
SQLITE_BUSY / database is locked

About energy

The problem occurred while I was trying to retrieve the energy consumption features of this socket, which had initially led me to the new energy monitoring code.

However, the traces now show that the blockage occurs before the creation/update of the energy features.

The existing energy feature is indeed correctly recognized:

zigbee2mqtt:Computer Station:switch:energy:energy matched=true

The blockage is triggered by the attempt to delete the old child_lock feature.

Other observation

During the freeze, the Energy Monitoring service continues to start its processes and indicates in particular:

Found 52 energy devices
Found 0 devices with both INDEX and thirty-minutes-consumption features

Then the SQLITE_BUSY errors appear in different parts of Gladys.

I also checked t_job: the SQLite → DuckDB migration jobs and DuckDB orphaned state purge are marked success.

Tested patch without success

I had also tested a modification of device.create.js to only trigger the state purge when keep_history actually changes from true to false:

const keepHistoryBeforeUpdate = deviceFeature.keep_history;

await deviceFeature.update(featureToUpdate, { transaction });

if (keepHistoryBeforeUpdate !== false && deviceFeature.keep_history === false) {
  deviceFeaturesIdsToPurge.push(deviceFeature.id);
}

This does not fix the problem: thanks to the additional logs, we now know that the freeze occurs earlier, during the destroy() of the obsolete feature.

Current state of the diagnosis

The reproducible blockage point is now quite precisely identified:

existingFeature.destroy({ transaction })

for:

zigbee2mqtt:Computer Station:access-control:mode:child_lock

We need to initiate an asynchronous task to destroy the states in order to continue the work.

Update: More Precise Cause of Freeze Identified

I continued to investigate the freeze during the update of a Zigbee2MQTT device.

The affected device is:

  • Computer Station
  • External ID: zigbee2mqtt:Computer Station

I temporarily added debug logs around the feature cleanup in device.create.js.

During the update, Gladys normally reaches the feature cleanup:

[DEBUG DEVICE CREATE] START zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE getDeviceInDb zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] AFTER getDeviceInDb zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE device update zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] AFTER device update zigbee2mqtt:Computer Station
[DEBUG DEVICE CREATE] BEFORE feature cleanup zigbee2mqtt:Computer Station
[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:switch:binary:state matched= true
[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:switch:power:power matched= true
[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:switch:current:current matched= true
[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:switch:voltage:voltage matched= true
[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:switch:energy:energy matched= true
[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:access-control:mode:child_lock matched= false
[DEBUG FEATURE DESTROY] BEFORE zigbee2mqtt:Computer Station:access-control:mode:child_lock
[DEBUG FEATURE CLEANUP] zigbee2mqtt:Computer Station:signal:integer:linkquality matched= true

There is never an AFTER log after attempting to delete child_lock.

The freeze therefore occurs here in device.create.js:

await existingFeature.destroy({ transaction });

Why This Feature Takes So Long to Delete

I checked the lines referencing this specific feature:

feature id:
557c3bba-bcc2-47e7-9f7f-f39614093509

energy_children    0
states             0
aggregates         509363
supported_options  0

The feature no longer has classic states in SQLite, but it still has 509,363 lines in:

t_device_feature_state_aggregate

The foreign key is configured as follows:

t_device_feature_state_aggregate.device_feature_id
    -> t_device_feature.id
    ON DELETE CASCADE

The aggregate table does have indexes, including:

t_device_feature_state_aggregate_device_feature_id
t_device_feature_state_aggregate_device_feature_id_type_created_at

Deleting the obsolete child_lock feature therefore triggers the cascading deletion of over 500,000 SQLite aggregates, directly within the device update transaction.

During this operation, other SQLite writes start to fail with:

SequelizeTimeoutError
SQLITE_BUSY: database is locked

For example, updates to t_service.failure_count performed by external integrations eventually time out.

Gladys’s HTTP request also eventually times out, giving the impression that the entire interface is frozen.

Gladys Already Handles This Problem in Another Code Path

It is interesting to note that device.destroy.js already has explicit protection against this type of situation when completely deleting a device.

The code counts the states and aggregates before deleting the device. When there are too many, it avoids immediate cascading deletion and instead triggers:

this.eventManager.emit(
  EVENTS.DEVICE.PURGE_STATES_SINGLE_FEATURE,
  deviceFeature.id
);

Device deletion is then interrupted so that histories can be cleaned up first.

For its part, device.purgeStatesByFeatureId.js intentionally deletes SQLite aggregates in batches:

DELETE FROM t_device_feature_state_aggregate WHERE id IN (
  SELECT id FROM t_device_feature_state_aggregate
  WHERE device_feature_id = :id
  LIMIT :limit
);

with a delay between batches.

The comments present in the code explicitly indicate that this operation is intended to avoid locking the database for a long time.

Possible Inconsistency Between the Two Deletion Paths

There therefore seems to be a difference in behavior between the complete deletion of a device and the deletion of an obsolete feature during an update.

For device deletion:

device.destroy()
    -> counts the states
    -> if there are too many:
       PURGE_STATES_SINGLE_FEATURE
       -> progressive cleanup

Whereas during the update of an existing device:

device.create()
    -> detects a feature that no longer exists
    -> existingFeature.destroy({ transaction })
    -> ON DELETE CASCADE SQLite
    -> synchronous deletion of approximately 509k aggregates
    -> prolonged SQLite lock

In my case, the obsolete feature is child_lock.

Why the Problem Initially Seemed Related to Energy

The problem was discovered when I tried to update my Computer Station outlet.

The outlet was already present in Gladys, but it was missing the energy consumption part that I wanted to retrieve during the update from Zigbee2MQTT.

Initially, the freeze therefore seemed related to the addition of the new energy features.

The traces ultimately show that the block occurs earlier: during the cleanup of old features, when Gladys attempts to delete child_lock.

It is therefore presumably not the creation of the new energy features that is causing the block, but the deletion of an old feature with a very large number of historical aggregates.

Correction Path

Simply replacing:

await existingFeature.destroy({ transaction });

with a PURGE_STATES_SINGLE_FEATURE event does not seem sufficient.

This would allow the history to be progressively purged, but the obsolete feature itself would remain in the database.

A mechanism would probably be needed to:

  1. detect that an obsolete feature has a lot of history;
  2. avoid its DELETE CASCADE in the update transaction;
  3. progressively purge its states and aggregates in the background;
  4. then delete the obsolete feature;
  5. optionally verify that it is still obsolete at the time of deletion, in case the integration exposed it again in the meantime.

I stop my investigations here. I hope this helps :slight_smile:

Perfect. Are you making a PR? Or do you want us to do it?

uh I’d prefer if you could do it please :slight_smile:

I think it’s a bit too technical for me to handle :confused:

Continuing the analysis, I realize that you have a lot of aggregated states in t_device_feature_state_aggregate that are no longer used. Everything is in DuckDB (states and aggregates calculated on the fly).

I think that the purge here only purges the states and not this table:

It might be better to delete the data and not implement the fix on a table that is supposed to be empty. I continue the investigation :detective:

I suspect you still have some unpurged aggregated states. I opened a PR to display them here Show the remaining SQLite aggregates in the DuckDB migration card by cicoub13 · Pull Request #2952 · GladysAssistant/Gladys · GitHub

But if you don’t want to wait, I think clicking the Purge button, then Clean the SQLite database. Your Zigbee update issue should disappear

I don’t understand, I already did this when DuckDB first arrived

I just clicked on purge and now I’m frozen again
I feel like I’m stuck..
To unblock myself, I need to purge, but to purge, I get blocked ahah help :face_with_spiral_eyes:

I think you never let it run to completion. Click Purge at a time when you don’t need Gladys and let it run. Even if you don’t get visual feedback, the purge is happening.

@cicoub13 are you not using the table anymore?

The table is no longer in use (at least its content). It should not be deleted as migrations still refer to it and I’m not sure what would happen if the table is completely removed.

If you’re comfortable, you can

  • Shut down Gladys properly
  • Back up the database files
  • TRUNCATE the table
  • Start Gladys

If you want more assurance about all this, you can wait for @pierre-gilles to give his opinion.

That’s what I was thinking of doing.
Thanks for your feedback, I’ll wait for his opinion, maybe he’ll have a better idea :slight_smile:

you can already go with that, it’s more than enough for an RW cache: Lot SSD NVME 256GB X2 - Accessoires informatique

Then on my Synology, I had set up the 2 SSDs for VM storage (not possible for Docker directly) but no backup though. Be careful as this is an unofficial method.

Return after cleaning the database

I finally managed to fix the problem (I am too impatient).

My SQLite database gladys-production.db had reached about 12 GB.

1. Integrity check with Gladys stopped

I started by creating a backup of my database, then I ran PRAGMA quick_check;.

On my NAS, the operation was extremely long due to I/O performance.

The quick_check took about 3 hours to complete, but eventually returned ok.

The SQLite database was therefore not corrupted.

During the check, the sqlite3 process was regularly in state D (disk sleep) and the counters /proc/<pid>/io showed that the reads were still progressing.

2. Identifying the problematic table

The main issue was with the table t_device_feature_state_aggregate.

The database was about 12 GB, and this table with its indexes seemed to represent the vast majority of the space used.

So I stopped Gladys before intervening on the database.

3. Deleting and recreating the table

Instead of doing a huge DELETE FROM t_device_feature_state_aggregate;, I chose to completely delete the table and then recreate it with its original schema and indexes.

Again, the operation was very long due to the NAS I/O.

A first attempt was interrupted after about 1 hour 30 minutes, due to a session SSH disconnection.

At that point, SQLite had already performed about 4.2 GB of reads (read_bytes: 4 197 961 728).

Since the COMMIT had not occurred, SQLite correctly rolled back the transaction and the old table was still present.

4. Second attempt with nohup

So I restarted the operation with nohup so that it would survive a potential SSH disconnection.

This time, the operation completed.

Some measurements during the DROP TABLE:

Elapsed time Data read
~22 min 0.73 GB
~1 h 04 2.75 GB
~1 h 32 4.20 GB
~1 h 50 5.02 GB
~2 h 20 6.02 GB
~2 h 30 9.44 GB
~2 h 39 10.81 GB

The complete operation eventually took about 2 hours 45 minutes.

The process was almost constantly in state D (disk sleep), with very little CPU used. The limiting factor was clearly the NAS I/O.

5. Verification after recreation

After the operation completed:

SELECT COUNT(*) FROM t_device_feature_state_aggregate;

returns 0.

The table was therefore successfully recreated empty.

I then ran PRAGMA wal_checkpoint(TRUNCATE);.

Result: 0|0|0.

The WAL was therefore correctly emptied.

6. Space recovered

The SQLite file still physically takes up about 12 GB, which is normal without VACUUM.

However:

  • page_count = 3 118 963
  • freelist_count = 3 098 841

This means that about 99.35% of the database pages are now free.

The space has not yet been returned to the file system, but SQLite can now reuse it.

I have not yet run a VACUUM on purpose.

7. Result after restarting Gladys

I then restarted Gladys.

Everything works normally.

And most importantly, I retested the problematic operation: modifying a device that was previously extremely slow/blocked.

This time, the device modification took a few seconds.

Conclusion

  • PRAGMA quick_check: OK, but about 3 hours
  • SQLite database: about 12 GB
  • t_device_feature_state_aggregate represented almost the entire database
  • First deletion attempt interrupted after ~1 hour 30 minutes
  • Complete second attempt: ~2 hours 45 minutes
  • freelist_count: 3 098 841 free pages out of 3 118 963, i.e., ~99.35%
  • After restart, Gladys works normally
  • The problematic device modification now takes a few seconds

The issue was indeed related to the explosion of t_device_feature_state_aggregate and the I/O performance required to work on this huge table.

Remaining tasks

  • Delete my backup
  • Run a vacuum
  • Add NVMe SSDs :sweat_smile:

Thanks @cicoub13 @mutmut