Bug 27048 - Add timestamps to verbose output of rebuild_zebra.pl
Summary: Add timestamps to verbose output of rebuild_zebra.pl
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Command-line Utilities (show other bugs)
Version: master
Hardware: All All
: P5 - low enhancement (vote)
Assignee: Martin Renvoize
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-11-18 09:50 UTC by Martin Renvoize
Modified: 2021-03-14 19:24 UTC (History)
9 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Text to go in the release notes:
Version(s) released in:
21.05.00,20.11.04


Attachments
Bug 27048: Add basic timekeeping to rebuild_zebra (2.14 KB, patch)
2020-11-18 10:37 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 27048: Add basic timekeeping to rebuild_zebra (4.03 KB, patch)
2020-11-18 12:01 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 27048: Add basic timekeeping to rebuild_zebra (4.08 KB, patch)
2021-01-28 11:18 UTC, David Nind
Details | Diff | Splinter Review
Bug 27048: (follow-up) Use DateTime instead of POSIX (2.27 KB, patch)
2021-02-23 12:18 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 27048: Add basic timekeeping to rebuild_zebra (4.14 KB, patch)
2021-02-28 17:36 UTC, Katrin Fischer
Details | Diff | Splinter Review
Bug 27048: (follow-up) Correction to elapsed printing (957 bytes, patch)
2021-03-01 14:01 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 27048: (follow-up) Correction to elapsed printing (1.27 KB, patch)
2021-03-03 15:27 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Renvoize 2020-11-18 09:50:26 UTC
It would be helpful to have timestamps added to the verbose option of rebuild_zebra.pl to see how long the rebuild has been running.
Comment 1 Martin Renvoize 2020-11-18 10:37:26 UTC
Created attachment 113773 [details] [review]
Bug 27048: Add basic timekeeping to rebuild_zebra
Comment 2 Martin Renvoize 2020-11-18 12:01:03 UTC
Created attachment 113780 [details] [review]
Bug 27048: Add basic timekeeping to rebuild_zebra

This patch adds a start time, end time and elapsed times on the 'records
exported' lines to the verbose output of the rebuild_zebra.pl script.

Test plan
1/ Run rebuild_zebra.pl -a -b -v
2/ Note the new timestamps included on the verbose output
3/ Signoff
Comment 3 David Cook 2021-01-27 23:37:28 UTC
Comment on attachment 113780 [details] [review]
Bug 27048: Add basic timekeeping to rebuild_zebra

Review of attachment 113780 [details] [review]:
-----------------------------------------------------------------

::: misc/migration_tools/rebuild_zebra.pl
@@ +848,5 @@
> +    my $now_pretty = POSIX::strftime("%H:%M:%S",localtime($now));
> +    my $elapsed_pretty = $d ? "[$d:$h:$m:$s]" : $h ? "[$h:$m:$s]" : $m ? "[$m:$s]" : "[$s]";
> +
> +    return "$now_pretty $elapsed_pretty";
> +}

Why not just use DateTime->now()->strftime("%H:%M:%S")?
Comment 4 David Nind 2021-01-28 11:18:34 UTC
Created attachment 115931 [details] [review]
Bug 27048: Add basic timekeeping to rebuild_zebra

This patch adds a start time, end time and elapsed times on the 'records
exported' lines to the verbose output of the rebuild_zebra.pl script.

Test plan
1/ Run rebuild_zebra.pl -a -b -v
2/ Note the new timestamps included on the verbose output
3/ Signoff

Signed-off-by: David Nind <david@davidnind.com>
Comment 5 Katrin Fischer 2021-02-07 12:50:14 UTC
(In reply to David Cook from comment #3)
> Comment on attachment 113780 [details] [review] [review]
> Bug 27048: Add basic timekeeping to rebuild_zebra
> 
> Review of attachment 113780 [details] [review] [review]:
> -----------------------------------------------------------------
> 
> ::: misc/migration_tools/rebuild_zebra.pl
> @@ +848,5 @@
> > +    my $now_pretty = POSIX::strftime("%H:%M:%S",localtime($now));
> > +    my $elapsed_pretty = $d ? "[$d:$h:$m:$s]" : $h ? "[$h:$m:$s]" : $m ? "[$m:$s]" : "[$s]";
> > +
> > +    return "$now_pretty $elapsed_pretty";
> > +}
> 
> Why not just use DateTime->now()->strftime("%H:%M:%S")?

Martin, can you answer David's question please?
Comment 6 Katrin Fischer 2021-02-17 20:50:29 UTC
This works well, still wondering about comment#3 - Failing QA to get attention :)
Comment 7 Martin Renvoize 2021-02-18 15:13:47 UTC
(In reply to David Cook from comment #3)
> Comment on attachment 113780 [details] [review] [review]
> Bug 27048: Add basic timekeeping to rebuild_zebra
> 
> Review of attachment 113780 [details] [review] [review]:
> -----------------------------------------------------------------
> 
> ::: misc/migration_tools/rebuild_zebra.pl
> @@ +848,5 @@
> > +    my $now_pretty = POSIX::strftime("%H:%M:%S",localtime($now));
> > +    my $elapsed_pretty = $d ? "[$d:$h:$m:$s]" : $h ? "[$h:$m:$s]" : $m ? "[$m:$s]" : "[$s]";
> > +
> > +    return "$now_pretty $elapsed_pretty";
> > +}
> 
> Why not just use DateTime->now()->strftime("%H:%M:%S")?

No major reason for using POSIX.. mostly I was avoiding more DateTime use.. but as it's a single call it's not terrible so can be swapped if needed.
Comment 8 Martin Renvoize 2021-02-23 12:09:12 UTC
I have a better answer now..

1. Because there is already president for using POSIX in the script
2. Because if we were switching to DateTime we should use dt_from_string to localise and be consistent with the rest of Koha.
3. Because DateTime::Durations don't print nicely without importing DateTime::Format::Duration which would add another dependency for a reasonably trivial functionality.
4. Because I hoped to 'keep it simple' by just working in seconds.. which it did.

I've tried to write a patch to switch to using DateTime and it ends up requiring extra dependencies, looking worse in the output and more complicated to work with :(
Comment 9 Martin Renvoize 2021-02-23 12:18:15 UTC
Created attachment 117201 [details] [review]
Bug 27048: (follow-up) Use DateTime instead of POSIX

This introduces additional dependancies and builds DateTime objects
multiple times.. I'm not sure it's worth it.
Comment 10 David Cook 2021-02-24 23:48:18 UTC
I think I must not have paid enough attention to the patch the first time around. I thought you were just adding timestamps to the loglines. I didn't realize that you were tracking elapsed time as well. 

I would do it differently but I'm not the one writing the code. I'll accept the reasons for using POSIX over DateTime, so no complaint from me.
Comment 11 Katrin Fischer 2021-02-28 17:36:46 UTC
Created attachment 117418 [details] [review]
Bug 27048: Add basic timekeeping to rebuild_zebra

This patch adds a start time, end time and elapsed times on the 'records
exported' lines to the verbose output of the rebuild_zebra.pl script.

Test plan
1/ Run rebuild_zebra.pl -a -b -v
2/ Note the new timestamps included on the verbose output
3/ Signoff

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Katrin Fischer <katrin.fischer.83@web.de>
Comment 12 Katrin Fischer 2021-02-28 17:37:24 UTC
I have obsoleted the datetime patch. I had already tested this before without and found it working well.
Comment 13 Jonathan Druart 2021-03-01 13:10:14 UTC
60 seconds:
exporting authority 13:06:38 [1:0]
61 seconds:
exporting authority 13:05:30 [1:1] 
54321 seconds:
exporting authority 13:07:06 [15:5:21]

It's not displayed as a duration and it's confusing IMO. It should at least display the HH, MM and SS parts on 2 digits.
Why not "15 hours, 5 minutes, 21 seconds" instead? Or "15h 5m 21s"?
Comment 14 Katrin Fischer 2021-03-01 13:43:22 UTC
(In reply to Jonathan Druart from comment #13)
> 60 seconds:
> exporting authority 13:06:38 [1:0]
> 61 seconds:
> exporting authority 13:05:30 [1:1] 
> 54321 seconds:
> exporting authority 13:07:06 [15:5:21]
> 
> It's not displayed as a duration and it's confusing IMO. It should at least
> display the HH, MM and SS parts on 2 digits.
> Why not "15 hours, 5 minutes, 21 seconds" instead? Or "15h 5m 21s"?

Hm, you are right. I guess my test db was too small, so the big numbers didn't make me suspicious. I think the second format you suggest would be better. 

Or:
Duration: 00:00:02
Comment 15 Martin Renvoize 2021-03-01 14:01:18 UTC
Created attachment 117452 [details] [review]
Bug 27048: (follow-up) Correction to elapsed printing
Comment 16 Martin Renvoize 2021-03-01 14:01:50 UTC
Fix the duration printing to take the form [00:00:07]
Comment 17 Jonathan Druart 2021-03-01 14:16:46 UTC
Martin, don't you think we should add a "elapsed" or "duration" to explain what it is?
Comment 18 Jonathan Druart 2021-03-03 15:27:01 UTC
Created attachment 117617 [details] [review]
Bug 27048: (follow-up) Correction to elapsed printing

JD Amended patch: Remove perlcritic error
"$d" is declared but not used at line 839, column 5.  Unused variables clutter code and make it harder to read.  (Severity: 3)
Comment 19 Jonathan Druart 2021-03-04 16:25:26 UTC
Pushed to master for 21.05, thanks to everybody involved!
Comment 20 Fridolin Somers 2021-03-08 15:44:13 UTC
Nice little enhancement, I choose to backport.

Pushed to 20.11.x for 20.11.04
Comment 21 Andrew Fuerste-Henry 2021-03-14 19:24:33 UTC
Enhancement, not backported t0 20.05