[Bug 43208] New: When searching action logs incorrectly formatted timestamps can slow responses
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Bug ID: 43208 Summary: When searching action logs incorrectly formatted timestamps can slow responses Initiative type: --- Sponsorship --- status: Product: Koha Version: Main Hardware: All OS: All Status: NEW Severity: normal Priority: P5 - low Component: REST API Assignee: koha-bugs@lists.koha-community.org Reporter: nick@bywatersolutions.com QA Contact: testopia@bugs.koha-community.org CC: tomascohen@gmail.com Target Milestone: --- Observed in production on a site with many rows in action logs, searching using the filters can take a long time. Testing the query on the command line I noticed it was fast if I used correct mySQL timestamps, however, the query took over a minute when the timestamps were formatted like 2026-07-31T00:00:00Z Below is the query I got from dumping the resultset as a query, it took over a minute to run, then if I correct the timestamp it takes seconds (SELECT `me`.`action_id`, `me`.`timestamp`, `me`.`user`, `me`.`module`, `me`.`action`, `me`.`object`, `me`.`info`, `me`.`interface`, `me`.`script`, `me`.`trace`, `me`.`diff`, `librarian`.`borrowernumber`, `librarian`.`cardnumber`, `librarian`.`surname`, `librarian`.`firstname`, `librarian`.`preferred_name`, `librarian`.`middle_name`, `librarian`.`title`, `librarian`.`othernames`, `librarian`.`initials`, `librarian`.`pronouns`, `librarian`.`streetnumber`, `librarian`.`streettype`, `librarian`.`address`, `librarian`.`address2`, `librarian`.`city`, `librarian`.`state`, `librarian`.`zipcode`, `librarian`.`country`, `librarian`.`email`, `librarian`.`phone`, `librarian`.`mobile`, `librarian`.`fax`, `librarian`.`emailpro`, `librarian`.`phonepro`, `librarian`.`B_streetnumber`, `librarian`.`B_streettype`, `librarian`.`B_address`, `librarian`.`B_address2`, `librarian`.`B_city`, `librarian`.`B_state`, `librarian`.`B_zipcode`, `librarian`.`B_country`, `librarian`.`B_email`, `librarian`.`B_phone`, `librarian`.`dateofbirth`, `librarian`.`branchcode`, `librarian`.`categorycode`, `librarian`.`dateenrolled`, `librarian`.`dateexpiry`, `librarian`.`password_expiration_date`, `librarian`.`date_renewed`, `librarian`.`gonenoaddress`, `librarian`.`lost`, `librarian`.`debarred`, `librarian`.`debarredcomment`, `librarian`.`contactname`, `librarian`.`contactfirstname`, `librarian`.`contacttitle`, `librarian`.`borrowernotes`, `librarian`.`relationship`, `librarian`.`sex`, `librarian`.`password`, `librarian`.`secret`, `librarian`.`auth_method`, `librarian`.`flags`, `librarian`.`userid`, `librarian`.`opacnote`, `librarian`.`contactnote`, `librarian`.`sort1`, `librarian`.`sort2`, `librarian`.`altcontactfirstname`, `librarian`.`altcontactsurname`, `librarian`.`altcontactaddress1`, `librarian`.`altcontactaddress2`, `librarian`.`altcontactaddress3`, `librarian`.`altcontactstate`, `librarian`.`altcontactzipcode`, `librarian`.`altcontactcountry`, `librarian`.`altcontactphone`, `librarian`.`smsalertnumber`, `librarian`.`sms_provider_id`, `librarian`.`privacy`, `librarian`.`privacy_guarantor_fines`, `librarian`.`privacy_guarantor_checkouts`, `librarian`.`checkprevcheckout`, `librarian`.`updated_on`, `librarian`.`lastseen`, `librarian`.`lang`, `librarian`.`login_attempts`, `librarian`.`overdrive_auth_token`, `librarian`.`anonymized`, `librarian`.`autorenew_checkouts`, `librarian`.`primary_contact_method`, `librarian`.`protected`, `patron`.`borrowernumber`, `patron`.`cardnumber`, `patron`.`surname`, `patron`.`firstname`, `patron`.`preferred_name`, `patron`.`middle_name`, `patron`.`title`, `patron`.`othernames`, `patron`.`initials`, `patron`.`pronouns`, `patron`.`streetnumber`, `patron`.`streettype`, `patron`.`address`, `patron`.`address2`, `patron`.`city`, `patron`.`state`, `patron`.`zipcode`, `patron`.`country`, `patron`.`email`, `patron`.`phone`, `patron`.`mobile`, `patron`.`fax`, `patron`.`emailpro`, `patron`.`phonepro`, `patron`.`B_streetnumber`, `patron`.`B_streettype`, `patron`.`B_address`, `patron`.`B_address2`, `patron`.`B_city`, `patron`.`B_state`, `patron`.`B_zipcode`, `patron`.`B_country`, `patron`.`B_email`, `patron`.`B_phone`, `patron`.`dateofbirth`, `patron`.`branchcode`, `patron`.`categorycode`, `patron`.`dateenrolled`, `patron`.`dateexpiry`, `patron`.`password_expiration_date`, `patron`.`date_renewed`, `patron`.`gonenoaddress`, `patron`.`lost`, `patron`.`debarred`, `patron`.`debarredcomment`, `patron`.`contactname`, `patron`.`contactfirstname`, `patron`.`contacttitle`, `patron`.`borrowernotes`, `patron`.`relationship`, `patron`.`sex`, `patron`.`password`, `patron`.`secret`, `patron`.`auth_method`, `patron`.`flags`, `patron`.`userid`, `patron`.`opacnote`, `patron`.`contactnote`, `patron`.`sort1`, `patron`.`sort2`, `patron`.`altcontactfirstname`, `patron`.`altcontactsurname`, `patron`.`altcontactaddress1`, `patron`.`altcontactaddress2`, `patron`.`altcontactaddress3`, `patron`.`altcontactstate`, `patron`.`altcontactzipcode`, `patron`.`altcontactcountry`, `patron`.`altcontactphone`, `patron`.`smsalertnumber`, `patron`.`sms_provider_id`, `patron`.`privacy`, `patron`.`privacy_guarantor_fines`, `patron`.`privacy_guarantor_checkouts`, `patron`.`checkprevcheckout`, `patron`.`updated_on`, `patron`.`lastseen`, `patron`.`lang`, `patron`.`login_attempts`, `patron`.`overdrive_auth_token`, `patron`.`anonymized`, `patron`.`autorenew_checkouts`, `patron`.`primary_contact_method`, `patron`.`protected` FROM `action_logs` `me` LEFT JOIN `borrowers` `librarian` ON `librarian`.`borrowernumber` = `me`.`user` LEFT JOIN `borrowers` `patron` ON `patron`.`borrowernumber` = `me`.`object` WHERE ( ( ( `module` = 'CRONJOBS' AND ( `timestamp` <= '2026-07-31T23:59:59Z' AND `timestamp` >= '2026-07-31T00:00:00Z' ) ) AND ( `me`.`timestamp` LIKE '%renew%' OR `me`.`user` LIKE '%renew%' OR `me`.`module` LIKE '%renew%' OR `me`.`action` LIKE '%renew%' OR `me`.`object` LIKE '%renew%' OR `me`.`info` LIKE '%renew%' OR `me`.`interface` LIKE '%renew%' ) ) ) ORDER BY `me`.`timestamp` DESC LIMIT 20); -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Nick Clemens (kidclamp) <nick@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Depends on| |29016 Referenced Bugs: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=29016 [Bug 29016] Improve performance of the Log viewer when working with a high volume of action logs -- You are receiving this mail because: You are the assignee for the bug. You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Andrew Fuerste-Henry <andrew@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |andrew@bywatersolutions.com -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Daniel B. <dbarden@cuyahogalibrary.org> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |dbarden@cuyahogalibrary.org -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|koha-bugs@lists.koha-commun |tomascohen@gmail.com |ity.org | -- You are receiving this mail because: You are watching all bug changes. You are the assignee for the bug.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |ASSIGNED -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Kristi Krueger <kkrueger@cuyahogalibrary.org> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |kkrueger@cuyahogalibrary.or | |g -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|ASSIGNED |Needs Signoff -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 --- Comment #1 from Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> --- Created attachment 202852 --> https://bugs.koha-community.org/bugzilla3/attachment.cgi?id=202852&action=edit Bug 43208: Use MySQL-compatible timestamps in log viewer filters The log viewer sends date filters as ISO 8601 timestamps (2026-07-31T00:00:00Z) via the q parameter. These values bypass the datetime conversion in attributes_from_api because they are nested inside DBIC operator keys (-and) which are not found in columns_info. MySQL cannot use the index on the timestamp column when comparing against the "T" separator format, causing full table scans on large action_logs tables. This patch formats the timestamps as "YYYY-MM-DD HH:MM:SS" which MySQL handles natively, allowing proper index usage. Test plan: 1. Apply patch 2. Have a site with many rows in action_logs (100k+) 3. Go to Tools -> Log viewer 4. Select a module (e.g. CRONJOBS), set a date range, search => SUCCESS: Results return in seconds, not minutes 5. Open browser dev tools, Network tab, verify the q parameter uses space-separated datetimes (not T/Z) 6. Sign off :-D Signed-off-by: Tomás Cohen Arazi <tomascohen@theke.io> -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 David Nind <david@davidnind.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |david@davidnind.com --- Comment #2 from David Nind <david@davidnind.com> --- Is there any "easy way" to do step 2 - generate 100k+ log entries table? -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Chip Halvorsen <Chip.Halvorsen@WestlakeLibrary.org> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |Chip.Halvorsen@WestlakeLibr | |ary.org -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 carthur@slolibrary.org <carthur@slolibrary.org> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |carthur@slolibrary.org -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 --- Comment #3 from Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> --- This is not easy to reproduce. Because many conditions affect how traversing the table (instead of the index) affects performance. What I think we could do is generate rows, and use MySQL's `EXPLAIN` statement to understand the effect of the change. Run this to generate rows: ```sql INSERT INTO action_logs (timestamp, user, module, action, object, info, interface) SELECT DATE_ADD('2025-01-01', INTERVAL FLOOR(RAND() * 500) DAY) as timestamp, 1, 'CATALOGUING', 'MODIFY', FLOOR(RAND() * 100000), 'test entry', 'intranet' FROM information_schema.columns a, information_schema.columns b LIMIT 50000; SELECT COUNT(*) as total_rows FROM action_logs; ``` Then you can use EXPLAIN to check if the queries use the index: ```sql EXPLAIN SELECT * FROM action_logs WHERE timestamp >= '2025-03-01T00:00:00Z' AND timestamp <= '2025-03-05T23:59:59Z'\G EXPLAIN SELECT * FROM action_logs WHERE timestamp >= '2025-03-01 00:00:00' AND timestamp <= '2025-03-05 23:59:59'\G ``` **ISO 8601 format (T separator)**: ``` id: 1 select_type: SIMPLE table: action_logs type: ALL possible_keys: timestamp_idx key: NULL key_len: NULL ref: NULL rows: 49938 Extra: Using where ``` **MySQL format (space separator)**: ```sql id: 1 select_type: SIMPLE table: action_logs type: range possible_keys: timestamp_idx key: timestamp_idx key_len: 4 ref: NULL rows: 520 Extra: Using index condition ``` And for time difference magnitude: ```sql SET profiling = 1; SELECT COUNT(*) FROM action_logs WHERE timestamp >= '2025-03-01T00:00:00Z' AND timestamp <= '2025-03-05T23:59:59Z'; SELECT COUNT(*) FROM action_logs WHERE timestamp >= '2025-03-01 00:00:00' AND timestamp <= '2025-03-05 23:59:59'; SHOW PROFILES; SET profiling = 0; ``` The `Duration` column is the key, on my local KTD I got this times: 5.35ms vs 0.13ms. 41× slower with the T separator format. -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 --- Comment #4 from Andrew Fuerste-Henry <andrew@bywatersolutions.com> --- With this patch applied I get error 400 (Bad Request) when attempting an action logs search with a date range. After applying the patches I did a restart_all and cleared my cache. Anything else I should be doing to make this work? -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Andrew Fuerste-Henry <andrew@bywatersolutions.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Needs Signoff |Failed QA -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|Failed QA |RESOLVED Resolution|--- |DUPLICATE --- Comment #5 from Tomás Cohen Arazi (tcohen) <tomascohen@gmail.com> --- This is a broader problem with how the `q` query parameter is processed. Moving to bug 43241 as it has a broader scope. *** This bug has been marked as a duplicate of bug 43241 *** -- You are receiving this mail because: You are watching all bug changes.
https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=43208 mteal@greenvillelibrary.org changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |mteal@greenvillelibrary.org -- You are receiving this mail because: You are watching all bug changes.
participants (1)
-
bugzilla-daemon@bugs.koha-community.org