John, I am really glad you're looking at this! I don't have the Python chops to solve this.
This application's deployment is the worst! It (a Docker container) runs along with 3 other weewx containers and another unrelated container on a little box in the cloud (1 vCPU, 1G), so you can see very little resources available. To add to the madness, I have the sdb and public_html directories mapped to, you guessed it, block storage. I do this because I frequently nuke & pave the server so it is a simple backup solution. I map public_html to the block storage because since creating NOAA reports is expensive, I like having a cache. All of the HTML is rsync'd to a web server so no performance requirement. I am trying to keep my costs as low as possible, and since weewx is effectively a batch system (with enough real-time via MQTT), eventually consistent is good enough for me for my hobby weather data right now. I doubt that the block storage is anything but a performance drag in my case. When I ran the exact same image with the same database I use in 'production,' I experienced the exact same issues with the database on local storage. All that said, I think we are burying the lede here. Matthew mentioned the abort logic if a report thread is already running, and I have used that (and max_wait) historically for situations just like this in the past. In all of this, I have not seen that message as I would expect to. If the code is still there, why is it not being invoked if that's exactly what is going on? And when weewx says it's exiting in the logs, it doesn't (or can't). To me, that is why we're seeing this lock stuff going on but I can't prove it. I hope this helps. FWIW, the fixes in beta4 (just out yesterday) got my performance (even as described above) down below the archive interval. But again, I think there's a bigger issue than my performance issue or environment. I hope this helps and again, I am happy to see you looking at this! On Tuesday, August 4, 2026 at 12:16:30 PM UTC-7 John Kline wrote: > Two more findings, both of which make the scan cost considerably worse > than I described. > > It runs once per generated file, not once per report cycle. > In weewx/cheetahgenerator.py, _getSearchList() is called at line 309, > inside the per-file loop that begins at line 270. That means the search > list extension — and therefore both table scans — runs once for every file > the skin generates. > beta3’s skin.conf ships 14 template sections: 12 under ToDate, plus > NOAA_month and NOAA_year. In steady state that’s 14 files per cycle, so 28 > full table scans. No stale_age is set on any section, so nothing is skipped > on that basis. > Past NOAA files are skipped cheaply — line 291 continues before the search > list is built, so an existing month or year file costs only an > os.path.exists() call. Only the current month and current year regenerate > each cycle. But that skip depends on the files being there. If your NOAA > directory doesn’t persist across container restarts, every restart > regenerates 13 years of monthly and yearly files — about 169 extra files, > each paying two scans, before it reaches the regular pages. Worth checking > whether that folder survives a restart in your setup. > > The scans happen before the forecast download, not after. > _archive_local_aqi_payload() is called at the top of the AQI block, ahead > of all the forecast-fetch code. In your log, the gap from “version > 2.1beta3” at 10:00:21 to “New forecast file downloaded” at 10:02:34 is 133 > seconds, and the scans are inside that window. > Also worth noting: every urlopen call in beta3 passes > DEFAULT_HTTP_TIMEOUT, which is 15 seconds. So no single HTTP request can > account for 133 seconds — that would take nine consecutive timeouts. The > time is more likely going to the database work. > One question that would help narrow the storage side: where does weewx.sdb > actually live — local disk on the Docker host, or a mounted volume? > SQLite’s documentation recommends against keeping database files on network > filesystems, since POSIX advisory locking is buggy or unimplemented on many > of them. Probably not what’s happening here, but it’s cheap to rule out. > > On Aug 4, 2026, at 11:41 AM, John Kline <[email protected]> wrote: > > > > I *may* have found the regression. It’s new in beta3 and it’s a full table > scan of the archive table on every report cycle. > > beta3 adds a local-AQI path to bin/user/new_belchertown.py. The core > helper: > > def _archive_latest_numeric(archive_manager, column_name): > row = archive_manager.getSql( > f"SELECT dateTime, {column_name} FROM archive " > f"WHERE {column_name} IS NOT NULL " > "ORDER BY dateTime DESC LIMIT 1" > ) > > _archive_local_aqi_payload() calls it for pm2_5_aqi, and if that comes > back empty, falls through to _archive_pm25_nowcast_payload(), which calls > it again for pm2_5. Neither function exists in 2.0 — all of this is new. > > dateTime is the archive table’s INTEGER PRIMARY KEY, so SQLite walks > backwards from the newest row. If the column has recent data it stops on > the first row and costs nothing. If the column exists in the schema but is > empty, SQLite has to read every row in the table to prove there’s no > non-NULL value anywhere. That’s a full scan, disk-bound, holding a SQLite > read lock for its entire duration — which is what blocks the archive writer > and produces “database is locked”. > > It’s gated on aqi_enabled, which defaults to 0. Your log shows “Xweather > AQI fallback cached to forecast.json”, so you have it on. > > I measured this on my own system — WeeWX 5.4.0, Pi 5, 785,666 archive > records (~7.5 years), NVMe. Same query shape, comparing a populated column > against an empty one: > > populated column (pm2_5): 0.001 s > empty column (hail), warm: 0.219 s > empty column (hail), cold: 1.120 s > > The cold number is after dropping caches. User CPU time is identical > between the warm and cold runs, so the extra second is purely waiting on > disk. > > Scaling to 13 years is roughly 1.75x my row count, so ~2 s per query cold, > ~4 s for the pair. On slower storage — an ordinary SD card, where random > page reads are an order of magnitude worse than NVMe — that could easily be > 15-30 s per query. > > Two queries would confirm it on your database: > > .timer on > SELECT dateTime, pm2_5_aqi FROM archive WHERE pm2_5_aqi IS NOT NULL ORDER > BY dateTime DESC LIMIT 1; > SELECT dateTime, pm2_5 FROM archive WHERE pm2_5 IS NOT NULL ORDER BY > dateTime DESC LIMIT 1; > > A parse error means the column isn’t in your schema and that one is > harmless. A fast result means the column has recent data. A slow result is > the bug. > > BTW, storing pm2_5_aqi in the database is a guaranteed way to get the > wrong answer for AQI. AQI is defined as a formula to be applied to the > average pm2.5 for any given time period. It is NOT defined as the average > of AQI calculations over said time period. I had a recent discussion with > a user of one of my air quality sensor extensions. By adding AQI to the > db, which he did, he was disabling the XType which comes with the > weewx-purple, weewx-airlink and weewx-airgradient extensions that would > properly calculate the AQI. And it saved virtually no time in getting the > wrong answer. All of the time is the database access and it's doing the > same accesses either way--one is getting AQI, the other pm2.5. > > On Aug 4, 2026, at 8:10 AM, John Kline <[email protected]> wrote: > > > If anyone wants to see where a report cycle is actually spending its time, > py-spy will tell you without modifying anything. Install it into a > throwaway venv and dump the running weewxd: > > python3 -m venv ~/pyspy-venv > ~/pyspy-venv/bin/pip install py-spy > pgrep -af weewxd > sudo ~/pyspy-venv/bin/py-spy dump –pid <pid> > > It attaches to the live process, prints a stack for every thread, and > detaches. No restart, no config change, no debug logging. > > I run weewx from a pip install, not in a container. My understanding is > that under Docker you’d run py-spy on the host and point it at the > host-side PID of the weewxd process rather than the one you see inside the > container, and that there may be a ptrace permission to sort out. I haven’t > done it, so someone who uses containers should confirm. > > Here’s one from my system (WeeWX 5.4.0, LiveSeasons (personal skin), Pi > 5), taken during a report cycle. I’ve cut the idle service threads: > > Thread 1767872 (idle): “MainThread” > read (serial/serialposix.py:565) > … > [seven idle service threads elided] > > Thread 379811 (active): “ReportThread” > execute (weedb/sqlite.py:249) > guarded_fn (weedb/sqlite.py:38) > getSql (weewx/manager.py:586) > firstGoodStamp (weewx/manager.py:326) > create_sync (weewx/manager.py:303) > sync (weewx/manager.py:307) > init (weewx/manager.py:142) > open (weewx/manager.py:187) > open_manager (weewx/manager.py:921) > getLatestForecastRows (user/nws.py:1702) > alerts (user/nws.py:1620) > respond (cheetah…alerts_inc….py:297) > handleCheetahInclude (Cheetah/Template.py:1712) > respond (cheetah_…alerts_html_tmpl….py:167) > generate (weewx/cheetahgenerator.py:335) > generate (weewx/cheetahgenerator.py:226) > generate (weewx/cheetahgenerator.py:226) > run (weewx/cheetahgenerator.py:166) > start (weewx/reportengine.py:482) > run (weewx/reportengine.py:252) > _bootstrap_inner (threading.py:1043) > _bootstrap (threading.py:1014) > > The report thread is named ReportThread, so it’s easy to find in the > output. > > Two things this makes visible. First, exactly what the cycle is doing at > that instant — which generator, which template, which query, right down to > the line. > > Second — and more to the point of this thread — it settles the concurrency > question directly. Every thread in the process is listed, so if two report > cycles are running at once, you get two entries with two distinct thread > IDs. One dump answers it. No inferring from CPU load, no relying on what > does or doesn’t get logged. > > For what it’s worth, I don’t think a second report thread is being > launched in the log posted here. weewx will launch one alongside a running > cycle, but only once the existing thread has been alive for max_wait > seconds (600 by default). In that log the report thread was about 300 > seconds old when the process took the database-locked exception and shut > down, and the restart resets the launch time — so the 600 s threshold never > gets close. That’s also why changing max_wait had no effect: neither branch > of that test is being reached. > > On Aug 4, 2026, at 6:26 AM, John Kline <[email protected]> wrote: > > > What did you see that told you it had no effect — a second report thread > launching, or the database is locked crashes continuing? > > If it’s the crashes, that’s expected. max_wait only suppresses the second > launch; the first report keeps holding the database either way, which is > what takes weewx down. > > If it’s an actual second thread launching, I’d want to see it — with > max_wait at 31.7 years. Worth confirming the setting landed in [StdReport] > and that weewx was restarted after the change. > > On Aug 4, 2026, at 6:11 AM, [email protected] <[email protected]> wrote: > > Yes, John, except changing max_wait had no effect in my case. > > On Tuesday, August 4, 2026 at 6:10:37 AM UTC-7 John Kline wrote: > >> One more thing, remembering that the OP is NOT focused on the database >> lock; but rather, another report cycle starting, adding >> >> [StdReport] >> max_wait = 999999999 >> >> will give the OP what he is asking for. >> >> On Aug 4, 2026, at 6:03 AM, John Kline <[email protected]> wrote: >> >> >> >> Small correction first: I didn’t show that. The >> version-logged-once-per-process point is your reading of the log, not >> something I demonstrated — and I don’t think the log can settle it either >> way. That engine started at 09:56 and died at 10:05:23, so it only ever got >> one report launch. A single version 2.1beta3 line is equally consistent >> with “logs once per process” and with “only one cycle ran.” You may well be >> right about the skin’s logging behavior, but that log isn’t evidence for it. >> >> On the substance, you’re right that a successful launch is silent. >> launch_report_thread() logs nothing on the happy path, so a report cycle >> can start with no trace in the weewx log. >> >> But a blocked launch is not silent: >> log.info("Launch of report thread aborted: existing report thread >> still running") >> >> Which leaves two possibilities: POST_LOOP never fired, because the >> OperationalError killed the main loop first — or the 10:00 cycle had >> already finished and a fresh one launched silently. The second requires the >> 10:00 cycle to have completed without ever logging Generated N files, which >> I’d want evidence for. >> >> On CPU: a busy CPU doesn’t distinguish a second run from the first one >> still grinding. The orphaned thread from 10:00 explains it by itself — >> nothing joined it, and self.thread gets reassigned on the next launch, so >> it just keeps running untracked. >> >> py-spy dump on the running process lists every thread with its stack. One >> StdReportEngine or two stops being a matter of interpretation at that point. >> >> On Aug 4, 2026, at 5:51 AM, [email protected] <[email protected]> wrote: >> >> Yes this is the behavior I have seen (Matthew is not hallucinating!) for >> a long time and it is not happening here. Also, John showed in the logs >> that the extension name and version are only printed to the console on the >> first run. Subsequent runs are silent until the message about how many >> files were generated, so while it looks like there is no evidence of a >> rogue report run, it's happening silently (and you can see it on CPU too). >> >> On Tuesday, August 4, 2026 at 5:40:37 AM UTC-7 John Kline wrote: >> >>> The code is still there. max_wait defaults to 60s, so it will start >>> another report cycle after 10m (assuming max_wait is overrridden somewher). >>> >>> def launch_report_thread(self, _event): >>> """Called after the packet LOOP. Processes any new data.""" >>> import weewx.reportengine >>> # Do not launch the reporting thread if an old one is still alive. >>> # To guard against a zombie thread (alive, but doing nothing) launch >>> # anyway if enough time has passed. >>> if self.thread and self.thread.is_alive(): >>> thread_age = time.time() - self.launch_time >>> if thread_age < self.max_wait: >>> log.info("Launch of report thread aborted: existing report thread still >>> running") >>> return >>> else: >>> log.warning("Previous report thread has been running" >>> " %s seconds. Launching report thread anyway.", thread_age) >>> >>> try: >>> self.thread = weewx.reportengine.StdReportEngine(self.config_dict, >>> self.engine.stn_info, >>> self.record, >>> first_run=not self.launch_time) >>> self.thread.start() >>> self.launch_time = time.time() >>> except threading.ThreadError: >>> log.error("Unable to launch report thread.") >>> self.thread = None >>> >>> > On Aug 4, 2026, at 5:24 AM, matthew wall <[email protected]> wrote: >>> > >>> > i might be hallucinating, but i remember at one point the code that >>> starts reports would check to see if a report was still running. if the >>> report was still running, it would skip that report and go to the next, >>> with a log entry that the report was skipped. >>> > >>> > a quick scan of reportengine.py does not show any of that behavior, so >>> i must be remembering logic from a previous implementation or something >>> that never made it to master. >>> > >>> > a per-report mutex/lock could be done in reportengine.py. but it might >>> be better to do it within each report, since the report has more detail >>> (and could thus provide better logs) about what is happening. >>> > >>> > i suppose that starting a thread for each report could lead to much >>> complexity if reports try to write to the database, not just read from it >>> > >>> > there have *always* been issues with shutting down the reporting >>> thread. if something in the report thread has a unresponsive file handle >>> open (e.g., slow nfs link) or a network socket open, then the thread does >>> not shut down immediately when the engine does a shutdown. >>> > >>> > m >>> > >>> > -- >>> > You received this message because you are subscribed to the Google >>> Groups "weewx-user" group. >>> > To unsubscribe from this group and stop receiving emails from it, send >>> an email to [email protected]. >>> > To view this discussion visit >>> https://groups.google.com/d/msgid/weewx-user/C69E9E4C-0B2F-44E8-B437-75990351E842%40gmail.com. >>> >>> >>> >> -- >> You received this message because you are subscribed to the Google Groups >> "weewx-user" group. >> To unsubscribe from this group and stop receiving emails from it, send an >> email to [email protected]. >> To view this discussion visit >> https://groups.google.com/d/msgid/weewx-user/d8fc89c7-0550-43b0-aaed-9a7dfb8f2711n%40googlegroups.com >> >> <https://groups.google.com/d/msgid/weewx-user/d8fc89c7-0550-43b0-aaed-9a7dfb8f2711n%40googlegroups.com?utm_medium=email&utm_source=footer> >> . >> >> -- > You received this message because you are subscribed to the Google Groups > "weewx-user" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to [email protected]. > To view this discussion visit > https://groups.google.com/d/msgid/weewx-user/72d6e8b1-5f4f-4adc-ae77-2a1ceada1276n%40googlegroups.com > > <https://groups.google.com/d/msgid/weewx-user/72d6e8b1-5f4f-4adc-ae77-2a1ceada1276n%40googlegroups.com?utm_medium=email&utm_source=footer> > . > > -- You received this message because you are subscribed to the Google Groups "weewx-user" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To view this discussion visit https://groups.google.com/d/msgid/weewx-user/c3aeb331-dac5-42cc-ac8e-ac692aabc8can%40googlegroups.com.
