ExportXMLWordPrintable

    • Type: Incident report
    • Resolution: Unresolved
    • Priority: Trivial
    • None
    • Affects Version/s: 7.0.28, 7.0.29
    • Component/s: Server (S)
    • None
    • Environment:

      Summary

      Since 2026-07-24 the server hangs 1-2 times per day (times appear random:
      13:12, 20:39, 08:57, 16:28, 14:11, 05:54, 05:42, 05:52 UTC on consecutive
      days). During each incident:

      • the preprocessing manager stops draining its queue; data ingestion from all
        proxies and trappers stops server-wide;
      • preprocessing manager process RSS grows unbounded (4.6 GB -> 18 GB in ~15
        minutes in the captured incident) while its process title freezes
        (queued 67, processed 400 values - stale);
      • the only remedy is kill -9 + restart of zabbix-server;
      • nothing relevant is logged at DebugLevel 3.

      The failure occurs EVERY DAY, sometimes twice a day. Below is evidence from
      two fully captured occurrences (2026-08-01 ~05:33-05:52 UTC and 2026-08-02
      ~04:20-05:03 UTC): per-2-second flight recorder, full core dumps of the
      preprocessing manager taken during the hang (gcore, 18 GB each), perf
      profile, -R diaginfo output and the server's own internal monitoring
      history. All other daily occurrences show the same external signature.

      Root-cause evidence

      1. GDB backtrace of the hung preprocessing manager (core taken 05:51 UTC)

      Main thread (LWP 3613074) - blocked in the history-cache retry loop:

      #0  0x00007f4e5a263f68 in nanosleep () from /lib64/libc.so.6
      #1  0x00007f4e5a263e6e in sleep () from /lib64/libc.so.6
      #2  0x00005618772ec33d in zbx_dc_flush_history ()
      #3  0x00005618772ec4d5 in dc_local_get_history_slot ()
      #4  0x00005618772ec87c in dc_local_add_history_text_bin_helper ()
      #5  0x00005618772ecc1e in zbx_dc_add_history_variant ()
      #6  0x00005618772bdec7 in preproc_flush_value_server ()
      #7  0x00005618772bba89 in zbx_pp_manager_thread ()
      #8  0x0000561877283b07 in zbx_thread_start ()
      ...
      

      (The sleep() inside the zbx_dc_flush_history symbol region corresponds to
      the inlined static hc_add_item_values() loop,
      src/libs/zbxcachehistory/cachehistory.c, release/7.0 branch):

      do
      {
              UNLOCK_CACHE;
              zabbix_log(LOG_LEVEL_DEBUG, "History cache is full. Sleeping for 1 second.");
              sleep(1);
              LOCK_CACHE;
      }
      while (SUCCEED != hc_clone_history_data(&data, item_value));
      

      All 50 preprocessing worker threads were idle:

      #0  pthread_cond_wait
      #1  pp_task_queue_wait ()
      #2  pp_worker_entry ()
      

      So the entire preprocessing pipeline was starved by the main thread being
      stuck in the cache-full retry loop.

      2. The history cache was NOT full at any point during the hang

      Server self-monitoring (1-minute averages, from history table), UTC:

      time wcache,history,pfree wcache,index,pfree history syncer busy% preproc mgr busy% trapper busy%
      05:20 95.1 73.4 24.7 2.4 9.8
      05:30 95.1 73.1 23.8 6.0 13.8
      05:33 95.1 73.3 25.0 39.6 25.6
      05:38 95.0 73.3 22.0 81.3 48.6
      05:41 - - 18.0 100.0 -
      05:45 95.1 73.4 29.1 100.0 73.7
      05:50 95.1 73.5 - - 76.0
      05:54 84.4 40.1 96.0 6.2 47.7 <- after restart, backlog flush
      05:55 20.8 12.3 100.0 7.3 11.3
      05:59 99.8 73.3 65.3 6.3 10.2 <- backlog fully absorbed

      Every failure path of hc_clone_history_data() is an allocation from the
      hc_mem pool (__hc_shmem_malloc_func), and
      zabbix[wcache,history,pfree] is computed from the same pool via
      zbx_hc_get_mem_stats() -> zbx_shmem_get_stats(hc_mem). The item reported
      ~95% free (~1.9 GB of 2 GB) for the whole 19-minute hang, yet the allocation
      kept failing every second. Values are capped at 64 KB
      (ZBX_HISTORY_VALUE_LEN), so a single oversized allocation cannot explain it.

      3. Flight recorder of the manager process (2-second sampling)

      Normal operation until 05:33:30, then the main loop wedges:

      time      cpu%   title idle  title during  state  wchan              voluntary_cs
      05:31:30   2.97   4.619336     5.000738    S      -                  50 814 819
      05:33:30   7.20   0.000811     6.381781    S      hrtimer_nanosleep  50 849 277
      05:38:11   3.33   0.000000    15.723774    R      -                  50 914 632
      05:43:40   2.88   0.000000    48.871697    S      hrtimer_nanosleep  ...
      05:44:30   2.62   0.000000   151.006037    S      hrtimer_nanosleep  50 937 430
      05:48:30   3.22   0.000000    51.905873    S      hrtimer_nanosleep  50 938 897
      05:49:44 234.74   0.000000     9.704901    S      hrtimer_nanosleep  50 939 651
      
      • From ~05:40 to ~05:49 the manager's voluntary context switches advance at
        ~1/second (50 937 006 -> 50 939 612 over 8.5 min) - exactly the sleep(1)
        retry cadence.
      • The process title update interval ("during N sec") stretches to 151 s -
        the manager main loop is stuck inside a single iteration.
      • zabbix[preprocessing_queue] stayed 0-1 before the incident; process RSS
        grew 4.6 GB -> 14 GB between 05:49 and 05:51 (18 GB core at 05:51) while
        ingress backed up.
      • TCP 10051: established connections grew 1 -> 14, send-q growing - proxies
        piling up, no data accepted.

      4. DB and syncers were healthy

      After kill -9 + restart at 05:52:40, the new server instance absorbed the
      entire proxy backlog: history cache went to 79% used / index 88% used,
      DB syncers ran at 100% busy for ~4 minutes, and by 05:59 everything was
      drained (pfree 99.8%). No slow queries were logged during the hang window
      (05:30-05:52). So this is not a DB bottleneck: the same DB swallowed the
      whole backlog in minutes right after restart.

      5. Possibly related observation

      Before the incident (for at least the preceding 24 h of recorder data)
      wcache,history,pfree plateaued at 95.1% and wcache,index,pfree at ~73%.
      After the restart the baselines are 99.8% and ~73% respectively. I.e. ~100 MB
      of hc_mem stayed resident for a long time before the hang and was never
      drained by syncers. Workload includes a large volume of TEXT values
      (Prometheus exporter payloads truncated to 64 KB, JSON master items), which
      is friendly to shared-memory fragmentation.

      Shared-memory allocator forensics (extracted from the core dump)

      We inspected the hc_mem / hc_index_mem arenas inside the core with gdb
      (symbols from the shipped binary; struct layouts from release/7.0
      include/zbxshmem.h and src/libs/zbxshmem/memalloc.c).

      Linear walk of the whole hc_mem arena (ground truth, size fields)

      Walking chunk-by-chunk from lo_bound to hi_bound via the left/right size
      fields gives a fully consistent picture (0 left/right size-field mismatches,
      100% arena coverage, sums match the accounting exactly):

      hc_mem (HistoryCacheSize=2G):
        chunks total:        2,315,462
        used chunks:         2,104,742   -> only 65.7 MB of payload (avg ~31 bytes/chunk!)
        free chunks:           210,720   -> 1.9 GB total free
        largest free chunk:     65,536 bytes (EXACT)
        free chunks >= 65,544:       0
        top free chunk sizes: 65536 x4, 65520 x1, 65512 x2, 65504 x1, 65496 x2, ...
      

      The preprocessing manager's local flush buffer was full
      (item_values_num == 256 == ZBX_MAX_VALUES_LOCAL) and contained at least one
      maximum-length TEXT value: len = zbx_db_strlen_n(value, 65536) + 1 = 65537
      bytes, which mem_proper_alloc_size() rounds to 65,544 bytes.

      **The largest free chunk in the entire 2 GB arena is 65,536 bytes - 8 bytes
      short of the required 65,544. The allocation can never succeed, so the
      manager sleeps in the retry loop forever.** This is the deterministic hang
      mechanism; it heals on restart only because the shm segment is recreated.

      Why the arena cannot coalesce: 2.1M pinned mini-chunks

      The 2 GB arena is shredded by ~2.1 million small live allocations (24-48
      bytes each, ~66 MB total) evenly scattered across the whole arena, i.e. one
      pinned mini-chunk roughly every 10 KB of address space. Free space therefore
      coalesces up to the ~64 KB ceiling and never beyond. These mini-chunks match
      the pre-incident anomaly: wcache,history,pfree plateaued at 95.1% for at
      least 27 h before the hang and returned to 99.8% only after restart - i.e.
      this population survives normal operation and is never drained by history
      syncers (stuck queued values for some items, or a leak of zbx_hc_data_t /
      small string chunks - we cannot tell from outside, but the core contains the
      answer).

      Free-list anomalies (secondary observation)

      The free-list linkage in the snapshot looks inconsistent with the linear
      walk: all 29 small-size buckets are empty; buckets[29] heads point at
      chunks that are marked USED (with sane, matching size fields - they look
      like live 40/48-byte structures); the real free chunks form long
      doubly-linked chains whose heads are not referenced by any bucket slot; one
      traversed node's link field contains ASCII payload data ("ExitType...""),
      i.e. list pointers overwritten by user data. Caveat: the 18 GB core was
      dumped over ~1 minute while history syncers kept modifying the shared
      memory, so part of this may be snapshot tearing rather than live corruption.
      The fragmentation finding above does NOT depend on this: it comes from the
      size-field walk, which is fully self-consistent.

      Why values pile up: history-sync starvation via trigger locks (follow-up analysis)

      Further core forensics and live observation identified where the 2.1M pinned
      mini-chunks come from - they are **legitimately queued values that history
      syncers skip forever**:

      • Walking cache->history_items in the core: 25,152 items tracked,
        1,063,115 queued values (sum of zbx_hc_item_t.values_num), all plain
        history values (flags=0, not LLD), stored as TEXT variants + their string
        chunks = the 2.1M pinned allocations.
      • cache->history_queue binary heap length = 23,152 - the items ARE in
        the sync queue; syncers pop them, fail to lock their triggers
        (zbx_dc_config_lock_triggers_by_history_items), and push them back
        unsynced, round after round, for 14+ hours.
      • Distribution is extremely skewed: one itemid held 111,273 queued values
        (an 1-second-interval item with a nodata() trigger); in the 2026-08-02
        occurrence the top four starved items (~75k values each) are 1/sec
        simple-check items with NO triggers at all - so besides trigger-lock
        skipping, plain sync-throughput collapse (see the perf finding below:
        O allocator scans under the shared cache lock) also starves high-rate
        items; whole hosts' item sets wedge together at discrete onset times.
      • Live confirmation on the current server instance: while the TimescaleDB
        policy_compression() background job runs (25-35 minutes daily on the
        history/history_uint hypertables; observed live), exactly one history
        syncer degrades to 72-73 s per batch holding ~1840 trigger locks
        (process title: processed 508 values, 1840 triggers in 73.293729 sec),
        while the other 23 syncers run 0.05-0.2 s batches. Items sharing those
        contended triggers are perpetually skipped and their values accumulate.
      • Environment note: PostgreSQL 15.12 with TimescaleDB 2.19.3, native
        compression enabled on all history/trends hypertables.

      What starts the starvation (timeline correlation)

      The onset correlates precisely with host-template linking events, not with
      any software update (OS/Zabbix packages were updated on Jul 24 after the
      first incident, during the same maintenance):

      • 2026-07-23 14:00 - six storage hosts were linked simultaneously to a
        PureStorage template (per host: one HTTP_AGENT master item polling an
        OpenMetrics exporter every 1 min, TEXT; 156 dependent items with
        PROMETHEUS_PATTERN; 7 dependent LLD rules; dozens of triggers, incl.
        multi-item expressions). First server hang: the following morning
        (Jul 24), daily ever since.
      • 2026-07-31 15:00 - one more host of the same type linked; the core dump
        shows the largest batch of stuck values stamps exactly Jul 31 15:00
        (11,844 of 15,000 sampled queued nodes).
      • Two more hosts linked Jul 30 03:00 / Jul 31 19:00 - matching further
        stuck-batch onset times observed in the core.
      • The value cache also spent most of Jul 25-26 in low-memory mode
        (aggravating trigger evaluation with direct DB reads).

      So the full causal chain is:

      1. Linking hosts with large dependent-item/LLD/trigger sets creates bursts
        of trigger evaluation and event generation; combined with daily 25-35 min
        TimescaleDB compression windows this degrades one history syncer to
        70+ second batches holding ~1800 trigger locks →
      2. trigger-locked items starve in the history cache queue; their values
        accumulate without bound (100k+ per item) →
      3. millions of small live chunks fragment hc_mem; largest coalescible free
        chunk converges to 65,536 bytes →
      4. first maximum-length (64 KB truncated) TEXT value → allocation of 65,544
        bytes can never succeed → preprocessing manager main thread sleeps
        forever in the DEBUG-level retry loop → server-wide ingestion stop.

      Proposed fixes (for discussion)

      1. Bound the retry loop in hc_add_item_values()
        (src/libs/zbxcachehistory/cachehistory.c): after N failed attempts (e.g.
        60-300 s) log at WARNING with itemid and requested size, drop the value
        and continue. Losing one value is strictly better than permanently
        stopping the entire server's data ingestion. Sketch:
         int retries = 0;
         while (SUCCEED != hc_clone_history_data(&data, item_value))
         {
             UNLOCK_CACHE;
             if (0 == retries % 30)
                 zabbix_log(LOG_LEVEL_WARNING, "history cache cannot fit value"
                         " (itemid:" ZBX_FS_UI64 " len:" ZBX_FS_SIZE_T "):"
                         " free_size=" ZBX_FS_UI64 " but no suitable chunk",
                         item_value->itemid, (zbx_fs_size_t)item_value->value.value_str.len,
                         hc_mem->free_size);
             if (++retries >= 300)
             {
                 zabbix_log(LOG_LEVEL_ERR, "dropping history value for itemid "
                         ZBX_FS_UI64 " after %d retries to avoid pipeline stall",
                         item_value->itemid, retries);
                 hc_free_data(data);
                 data = NULL;
                 break;  /* skip this value, continue with the rest */
             }
             sleep(1);
             LOCK_CACHE;
         }
         if (NULL == data)
             continue;
      
      1. Starvation protection in history sync: items repeatedly skipped due
        to locked triggers should eventually be synced anyway - e.g. after K
        consecutive skips write their values to history/trends without trigger
        processing (or with per-trigger fair queuing). Unbounded per-item queues
        are the fragmentation engine.
      1. Allocator hardening: for requests that go to the last bucket use
        best-fit instead of first-fit, and/or expose
        zbx_shmem_stats_t.max_chunk_size via a new internal item
        (e.g. zabbix[wcache,history,maxchunk]) so operators can alert on
        fragmentation before the hang. zbx_hc_get_mem_stats() already computes
        it; it is just not exposed.
      1. Observability: promote "History cache is full" from DEBUG to
        WARNING (rate-limited), and refresh the manager's process title while it
        is blocked in this loop (currently it shows stale queue numbers).

      Captured occurrence of 2026-08-02 - diaginfo and perf confirmation

      This daily occurrence reproduced the same state and was additionally
      captured with zabbix_server -R diaginfo, perf record and another 18 GB
      core dump:

      • Manager main-thread backtrace identical:
        nanosleep <- sleep <- zbx_dc_flush_history <- dc_local_get_history_slot <- ...
      • diaginfo=historycache output (Zabbix's own tool):
        Items:1868 values:961976
        Memory.data:
          size: free:2101194288 used:28528448
          chunks: free:227660 used:882374 min:24 max:65536     <-- largest free chunk
            buckets: ... 256+:221651
        Top.values:
          itemid:61559751 values:75224      <-- 1/sec DNS-check items, same
          itemid:61559701 values:75139          starved-by-trigger-locks family
          itemid:61559752 values:75099          as in the first incident
          itemid:61559700 values:75049
      

      I.e. ~2.03 GB reported free while the **largest free chunk is 65,536
      bytes** - the value the manager is blocked on cannot ever be placed.

      • diaginfo=preprocessing: queued count:21265562 queued size:13713539186
      • 21.2M values / 13.7 GB queued inside the blocked preprocessing manager
        (unbounded growth while the flush is stuck).
      • During the ~40-minute stall the manager main thread consumed 1-6% CPU
        with wchan hrtimer_nanosleep and ~1 voluntary context switch per second
        (the sleep(1) cadence); nothing was logged at DebugLevel 3.
      • perf record -p <manager> during the incident:
        59.1% of CPU samples in __mem_malloc (plus 14.5%
        zbx_dc_config_get_preprocessable_items, Duktape GC and jsonpath from
        worker threads). With ~221,000 free chunks accumulated in the allocator's
        last bucket, the first-fit scan in __mem_malloc() becomes O over a
        ~221k-element linked list FOR EVERY ALLOCATION, executed under the global
        history-cache lock. This is the "preprocessing manager at 100% CPU" phase
        operators observe, and it also collapses history syncer throughput (pop/
        push/get_item_values contend on the same LOCK_CACHE), which makes the
        backlog grow even for items without any triggers - a self-reinforcing
        spiral until the terminal 65,544-byte allocation blocks forever.

      Conclusions

      1. Primary defect: the history cache can degrade into a state where
        free_size is huge but no chunk can satisfy a maximum-size TEXT/LOG/BIN
        value, and hc_add_item_values() handles that by sleeping forever at
        DEBUG log level inside the single thread that feeds the entire server
        history pipeline in 7.0 (preprocessing manager main thread). One
        unsatisfiable value permanently stops all data ingestion server-wide.
      2. Contributing defect: millions of small history-cache chunks survive for
        days (never flushed/freed), acting as fragmentation pins. Their
        provenance needs identification (available in the core dump).
      3. The retry loop should not assume the condition is transient: after N
        failed retries the server should either drop the value with a WARNING
        (data loss for one value vs. total outage), fall back to a
        defragmentation/compaction path, or fail loudly.

      Additionally, two usability problems make this very hard to diagnose in
      production:

      • "History cache is full. Sleeping for 1 second." is LOG_LEVEL_DEBUG only -
        a production server at DebugLevel 3 hangs completely with zero log output.
        Please consider logging this at WARNING with rate limiting.
      • While the manager is stuck, its process title freezes, so ps shows a
        healthy-looking stale "queued 67" value.

      Impact

      Complete monitoring outage (no data from any proxy/trapper) 1-2 times per
      day until manual kill -9 + restart. HA does not help: the node stays "active"
      while ingesting nothing.

      Artifacts available on request

      • Full 18 GB core dump of the preprocessing manager taken during the hang
        (contains sensitive item payloads - we can run gdb commands against it and
        share outputs, or share allocator state, rather than upload the raw core);
      • zabbix_server binary + exact package versions;
      • flight-recorder TSV (2-second samples: CPU, RSS, wchan, /proc syscall,
        ctxt switches, TCP 10051 queue stats) covering 27 h around the incident;
      • internal monitoring history (wcache/syncer/trapper busy) export;
      • server configuration file.

      Steps to reproduce

      Not reproducible on demand; occurs 1-2 times/day on this production instance
      under sustained load with many dependent items and large TEXT master values.
      Happy to gather any additional diagnostics during the next occurrence - we
      have an automated capture harness (strace, per-thread sampling, tcpdump,
      log-level bump, diaginfo) triggered by a watchdog.

        1. bt_20260802.txt
          19 kB
          Viktor Man
        2. diaginfo_20260802.txt
          10 kB
          Viktor Man
        3. hc-hang-fix.patch
          5 kB
          Viktor Man
        4. live-state-snapshot-20260801-1724.txt
          130 kB
          Viktor Man
        5. perf-report-20260802.txt
          4 kB
          Viktor Man
        6. watchdog-flightrecorder-jul31-aug01.tsv
          5.22 MB
          Viktor Man

            Assignee:
            Tymon Nowak
            Reporter:
            Viktor Man
            Votes:
            3 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated: