Bug 28692 - Reduce DB action_log table size
Summary: Reduce DB action_log table size
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Database (show other bugs)
Version: Main
Hardware: All All
: P5 - low major (vote)
Assignee: Jonathan Druart
QA Contact: Marcel de Rooy
URL:
Keywords:
: 28700 (view as bug list)
Depends on:
Blocks:
 
Reported: 2021-07-08 14:51 UTC by Peter Vashchuk
Modified: 2022-12-12 21:23 UTC (History)
10 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Small patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
21.11.00


Attachments
Bug 28692 - log without indentation to decrease DB action_log table size (5.95 KB, patch)
2021-07-08 14:55 UTC, Peter Vashchuk
Details | Diff | Splinter Review
Bug 28692: log without indentation to decrease DB action_log table size (6.18 KB, patch)
2021-07-12 13:59 UTC, Peter Vashchuk
Details | Diff | Splinter Review
Bug 28692: log without indentation to decrease DB action_log table size (6.17 KB, patch)
2021-10-04 10:55 UTC, Peter Vashchuk
Details | Diff | Splinter Review
Bug 28700: Get from storage before log actions (5.81 KB, patch)
2021-11-04 10:19 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 28692: Get from storage before log actions (5.81 KB, patch)
2021-11-08 12:19 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 28692: Get from storage before log actions (5.90 KB, patch)
2021-11-12 10:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28962: (QA follow-up) Add module (618 bytes, patch)
2021-11-12 10:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28962: (QA follow-up) Sort hash keys of unblessed (941 bytes, patch)
2021-11-12 10:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28962: (QA follow-up) Fix test for objects (1.29 KB, patch)
2021-11-12 10:52 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: Correctly prefix "item " for Koha::Item MODIFY logs (1.02 KB, patch)
2021-11-15 11:07 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 28692: (QA follow-up) Add module (618 bytes, patch)
2021-11-15 13:01 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: (QA follow-up) Sort hash keys of unblessed (941 bytes, patch)
2021-11-15 13:02 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: (QA follow-up) Fix test for objects (1.31 KB, patch)
2021-11-15 13:02 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: (QA follow-up) Fix test for objects (1.27 KB, patch)
2021-11-15 13:12 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: Get from storage before log actions (5.90 KB, patch)
2021-11-15 13:45 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: (QA follow-up) Add module (618 bytes, patch)
2021-11-15 13:45 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: (QA follow-up) Sort hash keys of unblessed (941 bytes, patch)
2021-11-15 13:45 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: (QA follow-up) Fix test for objects (1.43 KB, patch)
2021-11-15 13:45 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 28692: (follow-up) Add tests (2.76 KB, patch)
2021-11-15 13:45 UTC, Marcel de Rooy
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Peter Vashchuk 2021-07-08 14:51:53 UTC

    
Comment 1 Peter Vashchuk 2021-07-08 14:55:17 UTC Comment hidden (obsolete)
Comment 2 Jonathan Druart 2021-07-12 08:38:52 UTC
Yes, that makes sense. Shouldn't we actually have the Dump call in logaction and pass the Koha::Hold object?

We could have something like
  if ( ref($infos) eq 'Koha::Hold') {
    $infos = Data::Dumper->new([$infos->unblessed], [qw(hold)])->Indent(0)->Sortkeys(1)->Dump;
  }

What do you think?

Don't forget to run the koha-qa.pl script before you submit a patch ;)
Comment 3 Marcel de Rooy 2021-07-12 09:57:50 UTC
Data::Dumper->new([$self->unblessed], [qw(item)])->Indent(0)->Sortkeys(1)->Dump )

Hmm Not really like the looks of this statement personally. Not so intuitive as the easy functional interface print Dumper($a,$b)
Since we use that so often, this might be confusing.

Another thought:
Why not set a BEGIN block in C4/Log with something like:
$Data::Dumper::Indent = 0;
etc

And if you like preferences ;) you might wanna control this value somehow..
Comment 4 Peter Vashchuk 2021-07-12 13:59:07 UTC
Created attachment 122782 [details] [review]
Bug 28692: log without indentation to decrease DB action_log table size

Indentation symbols like spaces and newlines take up a large amount of
extra space. Example: fully indented action_log item MODIFY record
weighs from 1.6 to 370 KB while the version of it without any
indentation takes 1.1 to 46 KB accordingly.

This changes logaction subroutine to perform a special transformation,
if$info came as known object, that adds Indent(0) parameter of
Data::Dumper to output without indentation.

To reproduce for item:
1) edit any item you see fit, save it.
2) check the action_logs table and find there a newly created MODIFY
item row, "info" column of that contains dumped data, see that it has
indentation, optional: check and note about the size of it.
3) apply the patch.
4) edit that item again and save it afterwards.
5) "info" column of the newly created row should contain non-indented
text now. If you did check the size of the previous dump, compare it
with this new one, check the difference it makes.

To reproduce for hold:
1) in syspref set HoldsLog to Log.
1) go to the biblio page and suspend and resume any hold you see fit.
2) check the action_logs table and find there a newly created SUSPEND
item row, "info" column of that contains dumped data, see that it has
indentation, optional: check and note about the size of it.
3) apply the patch.
4) edit that item again and save it afterwards.
5) "info" column of the newly created row should contain non-indented
text now. If you did check the size of the previous dump, compare it
with this new one, check the difference it makes.
Comment 5 Andrii Nugged 2021-08-18 15:45:12 UTC
Note: Jonathan, Bug 28700 has much bigger impact on logs records size
Comment 6 David Cook 2021-09-27 06:31:36 UTC
Interested in this as I recently was looking at a 30GB Koha database where 20GB was in the action_log table alone.
Comment 7 Fridolin Somers 2021-09-28 06:59:09 UTC
Looks great.

But :
Koha/Item.pm
-          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, "item " . Dumper( $self->unblessed ) );
+          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, "item " . $self );

This is a string concatenation, seems wrong.
Comment 8 Joonas Kylmälä 2021-10-02 14:06:30 UTC
(In reply to Fridolin Somers from comment #7)
> Looks great.
> 
> But :
> Koha/Item.pm
> -          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, "item "
> . Dumper( $self->unblessed ) );
> +          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, "item "
> . $self );
> 
> This is a string concatenation, seems wrong.

Yup, it's a bug. Marking as FQA to get Petro's attention.
Comment 9 Peter Vashchuk 2021-10-04 10:55:56 UTC
Created attachment 125692 [details] [review]
Bug 28692: log without indentation to decrease DB action_log table size

Indentation symbols like spaces and newlines take up a large amount of
extra space. Example: fully indented action_log item MODIFY record
weighs from 1.6 to 370 KB while the version of it without any
indentation takes 1.1 to 46 KB accordingly.

This changes logaction subroutine to perform a special transformation,
if$info came as known object, that adds Indent(0) parameter of
Data::Dumper to output without indentation.

To reproduce for item:
1) edit any item you see fit, save it.
2) check the action_logs table and find there a newly created MODIFY
item row, "info" column of that contains dumped data, see that it has
indentation, optional: check and note about the size of it.
3) apply the patch.
4) edit that item again and save it afterwards.
5) "info" column of the newly created row should contain non-indented
text now. If you did check the size of the previous dump, compare it
with this new one, check the difference it makes.

To reproduce for hold:
1) in syspref set HoldsLog to Log.
1) go to the biblio page and suspend and resume any hold you see fit.
2) check the action_logs table and find there a newly created SUSPEND
item row, "info" column of that contains dumped data, see that it has
indentation, optional: check and note about the size of it.
3) apply the patch.
4) edit that item again and save it afterwards.
5) "info" column of the newly created row should contain non-indented
text now. If you did check the size of the previous dump, compare it
with this new one, check the difference it makes.
Comment 10 Marcel de Rooy 2021-10-26 11:52:01 UTC
(In reply to Marcel de Rooy from comment #3)

Looking again here, thx for responding :)
Comment 11 Marcel de Rooy 2021-10-26 11:54:52 UTC
Will be testing this a bit. But can tell you now that we need tests. Might be adding one, not sure yet.
Comment 12 Marcel de Rooy 2021-10-26 12:17:32 UTC
I tend to think that we should solve this issue and the unblessed-thing on bug 28700 together.

    if ( ref $infos eq 'Koha::Hold' ) {
        $varname = 'hold';
    } elsif ( ref $infos eq 'Koha::Item' ) {
        $varname = 'item';
    }
    if ($varname) {
        $infos = Data::Dumper->new( [ $infos->unblessed ], [$varname] )->Indent(0)->Sortkeys(1)->Dump;
    }

This is a bit ugly :)
Comment 13 Martin Renvoize 2021-10-26 12:27:41 UTC
The 'infos' parameter of logaction is really inconsistent in general.. I'd love to see it consistently be JSON myself.. as a universally easy thing to encode/decode with handling built-in at the object level for consistent handling of numbers and dates.

I also prefer 'diff' to 'whole object dumps'.. when improving the change log for patron modification I chose to create a json representation of just the changed fields rather than dumping the whole patron object into the logs... having said that.. some of the log output I've since learnt depends on doing diffs at the point of display so need whole object dumps at the moment.
Comment 14 Martin Renvoize 2021-10-26 12:29:52 UTC
See https://git.koha-community.org/Koha-community/Koha/src/branch/master/Koha/Patron.pm#L307-L348 for the JSON 'changed field' structure we opted for.
Comment 15 Martin Renvoize 2021-10-26 12:32:34 UTC
and see https://git.koha-community.org/Koha-community/Koha/src/branch/master/koha-tmpl/intranet-tmpl/prog/en/modules/tools/viewlog.tt for the jsdiff based diff we display.

Removing whitespace will confuse that diff display I reckon... certainly worth checking for regressions there.
Comment 16 Martin Renvoize 2021-10-26 13:20:20 UTC
I think we should grab the more general handling from the middle two patches on bug 28700 for here.
Comment 17 Jonathan Druart 2021-11-04 10:19:56 UTC
Created attachment 127289 [details] [review]
Bug 28700: Get from storage before log actions

To make sure we have logging the values from DB.
It will reduce DB action_log table size when we log the full object and
it contains DateTime object.
Comment 18 Jonathan Druart 2021-11-04 10:24:24 UTC
This patch is more or less the same as Petro, but 1. it calls get_from_storage and 2. deals with any Koha::Object we will pass.

There is much more to do for logging correctly, this patch is only impacting calls where Dumper($object->unblessed) were passed to logaction.

We certainly need to improve the whole thing and pass an object from everywhere, deal with logic in logaction (depending on the objects we have), log a pre/post stringified versions of the object in 2 different columns (to allow a nice diff from the UI), and finally stringify using JSON (that is currently done only for acquisition logs and patron modification, which is quite inconsistent). This is definitely for a separate bug report, but I think we should focus on it (as a team) for 22.05.
Comment 19 Martin Renvoize 2021-11-08 12:19:44 UTC
Created attachment 127446 [details] [review]
Bug 28692: Get from storage before log actions

To make sure we have logging the values from DB.
It will reduce DB action_log table size when we log the full object and
it contains DateTime object.

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 20 Martin Renvoize 2021-11-08 12:21:05 UTC
Great, this is a good first step and enough at this late stage in the cycle for the next release in my opinion.

I'd have been tempted to drop the 'item' prepension, but that would lead to questions like "Should we run a DB update to fix existing cases"

Signing off.
Comment 21 Marcel de Rooy 2021-11-12 09:56:58 UTC
QA: Looking here
Comment 22 Marcel de Rooy 2021-11-12 09:57:12 UTC
Promising: Undefined subroutine &C4::Log::Dumper called at /usr/share/koha/C4/Log.pm line 81
Comment 23 Marcel de Rooy 2021-11-12 09:59:25 UTC
(In reply to Martin Renvoize from comment #20)
> Great, this is a good first step and enough at this late stage in the cycle
> for the next release in my opinion.
> 
> I'd have been tempted to drop the 'item' prepension, but that would lead to
> questions like "Should we run a DB update to fix existing cases"
> 
> Signing off.

How did you test it? First thing is a crash on missing module..
Comment 24 Marcel de Rooy 2021-11-12 10:33:40 UTC
+        $infos = Dumper( $infos->unblessed );
+
+        if ( $infos->isa('Koha::Item') && $modulename eq 'CATALOGUING' && $actionname eq 'MODIFY' ) {

Ha. If you change the variable to a string, it wont be a Koha::Item anymore ;)
Will fix it.
Comment 25 Marcel de Rooy 2021-11-12 10:46:54 UTC
Koha::Item

Not sure if there was an idea to log the item version before we store (get_from_storage call) but we only save the current stage:

    my $result = $self->SUPER::store;
    if ( $log_action && C4::Context->preference("CataloguingLog") ) {
        $action eq 'create'
          ? logaction( "CATALOGUING", "ADD", $self->itemnumber, "item" )
          : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, $self );
    }

We already super stored. So if we wanted the version without the changes like the BIBLIO BEFORE then we should move the super store here?
In that case I would also add a BEFORE.
Comment 26 Marcel de Rooy 2021-11-12 10:47:48 UTC
-    my $result = $self->SUPER::store;
     if ( $log_action && C4::Context->preference("CataloguingLog") ) {
         $action eq 'create'
           ? logaction( "CATALOGUING", "ADD", $self->itemnumber, "item" )
           : logaction( "CATALOGUING", "MODIFY", $self->itemnumber, $self );
     }
+    my $result = $self->SUPER::store;
Comment 27 Marcel de Rooy 2021-11-12 10:52:23 UTC
Created attachment 127574 [details] [review]
Bug 28692: Get from storage before log actions

To make sure we have logging the values from DB.
It will reduce DB action_log table size when we log the full object and
it contains DateTime object.

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 28 Marcel de Rooy 2021-11-12 10:52:26 UTC
Created attachment 127575 [details] [review]
Bug 28962: (QA follow-up) Add module

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 29 Marcel de Rooy 2021-11-12 10:52:30 UTC
Created attachment 127576 [details] [review]
Bug 28962: (QA follow-up) Sort hash keys of unblessed

Trivial add. Reads much better. And might help future diffs.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 30 Marcel de Rooy 2021-11-12 10:52:34 UTC
Created attachment 127577 [details] [review]
Bug 28962: (QA follow-up) Fix test for objects

Simpler to check the ref instead of isa.
Fix the bug where object is first stringified and then tested for
being a Koha::Item.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 31 Marcel de Rooy 2021-11-12 10:55:18 UTC
Development and testing seems to be done too hastily. Three follow-ups ;)
Comment25 and 26 leaving open.
Note that I didnt have time to add some additional test for logaction. But you are  welcome to still add it, Jonathan.
Comment 32 Jonathan Druart 2021-11-15 11:04:31 UTC
(In reply to Marcel de Rooy from comment #30)
> Created attachment 127577 [details] [review] [review]
> Bug 28962: (QA follow-up) Fix test for objects
> 
> Simpler to check the ref instead of isa.
> Fix the bug where object is first stringified and then tested for
> being a Koha::Item.
> 
> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>

This is not correct, we have modules in Koha:: that are not Koha::Object-based objects.
Comment 33 Jonathan Druart 2021-11-15 11:07:13 UTC
Created attachment 127630 [details] [review]
Bug 28692: Correctly prefix "item " for Koha::Item MODIFY logs

or the isa won't work
Comment 34 Jonathan Druart 2021-11-15 11:09:20 UTC
Comments 25 and 26 need more attention, and tests are missing.

Help welcomed.
Comment 35 Marcel de Rooy 2021-11-15 12:43:11 UTC
(In reply to Jonathan Druart from comment #34)
> Comments 25 and 26 need more attention, and tests are missing.
> 
> Help welcomed.

Revisiting it now
Comment 36 Marcel de Rooy 2021-11-15 13:01:57 UTC
Created attachment 127639 [details] [review]
Bug 28692: (QA follow-up) Add module

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 37 Marcel de Rooy 2021-11-15 13:02:01 UTC
Created attachment 127640 [details] [review]
Bug 28692: (QA follow-up) Sort hash keys of unblessed

Trivial add. Reads much better. And might help future diffs.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 38 Marcel de Rooy 2021-11-15 13:02:05 UTC Comment hidden (obsolete)
Comment 39 Marcel de Rooy 2021-11-15 13:12:38 UTC
Created attachment 127642 [details] [review]
Bug 28692: (QA follow-up) Fix test for objects

Fix the bug where object is first stringified and then tested for
being a Koha::Item.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 40 Marcel de Rooy 2021-11-15 13:45:05 UTC
Created attachment 127645 [details] [review]
Bug 28692: Get from storage before log actions

To make sure we have logging the values from DB.
It will reduce DB action_log table size when we log the full object and
it contains DateTime object.

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 41 Marcel de Rooy 2021-11-15 13:45:09 UTC
Created attachment 127646 [details] [review]
Bug 28692: (QA follow-up) Add module

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 42 Marcel de Rooy 2021-11-15 13:45:13 UTC
Created attachment 127647 [details] [review]
Bug 28692: (QA follow-up) Sort hash keys of unblessed

Trivial add. Reads much better. And might help future diffs.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 43 Marcel de Rooy 2021-11-15 13:45:17 UTC
Created attachment 127648 [details] [review]
Bug 28692: (QA follow-up) Fix test for objects

Fix the bug where object is first stringified and then tested for
being a Koha::Item.

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 44 Marcel de Rooy 2021-11-15 13:45:21 UTC
Created attachment 127649 [details] [review]
Bug 28692: (follow-up) Add tests

Test plan:
Run t/db_dependent/Log.t

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 45 Marcel de Rooy 2021-11-15 13:46:16 UTC
(In reply to Jonathan Druart from comment #34)
> Comments 25 and 26 need more attention, and tests are missing.
> 
> Help welcomed.

Added tests.
It seems to me that we should postpone comments 25 and 26. They feel a bit out of scope here too. We want to reduce log size here.
Comment 46 Marcel de Rooy 2021-11-15 13:46:40 UTC
(In reply to Jonathan Druart from comment #32)
> (In reply to Marcel de Rooy from comment #30)
> > Created attachment 127577 [details] [review] [review] [review]
> > Bug 28962: (QA follow-up) Fix test for objects
> > 
> > Simpler to check the ref instead of isa.
> > Fix the bug where object is first stringified and then tested for
> > being a Koha::Item.
> > 
> > Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
> 
> This is not correct, we have modules in Koha:: that are not
> Koha::Object-based objects.

Fixed
Comment 47 Jonathan Druart 2021-11-16 13:01:22 UTC
Pushed to master for 21.11, thanks to everybody involved!
Comment 48 Kyle M Hall 2021-11-19 16:44:16 UTC
Doesn't apply to 21.05.x. Please rebase and let me know if you think this should be backported.
Comment 49 Marcel de Rooy 2022-03-28 08:47:46 UTC
(In reply to Kyle M Hall from comment #48)
> Doesn't apply to 21.05.x. Please rebase and let me know if you think this
> should be backported.

It really should have :) My 20.11 logs were growing steadily with these datetime object dumps. The rebase was trivial..
Comment 50 Marcel de Rooy 2022-03-28 08:49:17 UTC
*** Bug 28700 has been marked as a duplicate of this bug. ***