Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Wrong "Time Elapsed" in core:archive output #8621

Closed
mattab opened this issue Aug 21, 2015 · 7 comments
Closed

Wrong "Time Elapsed" in core:archive output #8621

mattab opened this issue Aug 21, 2015 · 7 comments
Assignees
Labels
Bug For errors / faults / flaws / inconsistencies etc.
Milestone

Comments

@mattab
Copy link
Member

mattab commented Aug 21, 2015

See below:

INFO [2015-08-21 16:03:03] Will pre-process for website id = 103, period = day, date = last52
INFO [2015-08-21 16:03:03] - pre-processing all visits
INFO [2015-08-21 16:03:46] Archived website id = 103, period = day, 0 segments, 0 visits in last last52 days, 0 visits today, Time elapsed: 0.002s

  • Got Time elapsed: 0.002s
  • Expected Time elapsed: 43s (16:03:46 - 16:03:03)
@mattab mattab added the Bug For errors / faults / flaws / inconsistencies etc. label Aug 21, 2015
@mattab mattab added this to the 2.15.0 milestone Aug 21, 2015
@quba
Copy link
Contributor

quba commented Aug 21, 2015

0 visits in last last52 days, 0 visits today

This also looks weird. It took 43s to calculate 52 empty days? I guess I've seen such issues recently - archiving incorrectly outputs 0 visits.

@tsteur
Copy link
Member

tsteur commented Aug 24, 2015

FYI: Archiving an empty day taking about 1s sounds realistic

@mnapoli
Copy link
Contributor

mnapoli commented Aug 24, 2015

Got valid numbers:

capture d ecran 2015-08-24 a 14 50 07

@tsteur
Copy link
Member

tsteur commented Aug 31, 2015

It works for me as well and can't reproduce it either. Also had a look at the code which looks good. Maybe your system had some kind of problems writing the log line. I'd recommend to try to reproduce with latest version from master and if you can reproduce it maybe quickly debug it?

@mattab
Copy link
Member Author

mattab commented Aug 31, 2015

I just again re-started the archiving script and got a weird result on first website:

INFO [2015-08-31 07:03:06] START
INFO [2015-08-31 07:03:06] Starting Piwik reports archiving...
INFO [2015-08-31 07:03:06] Will pre-process for website id = 1, period = day, date = last52
INFO [2015-08-31 07:03:06] - pre-processing all visits
INFO [2015-08-31 07:03:08] - pre-processing segment 1/2 browserCode!=FF,eventAction!=ab
INFO [2015-08-31 07:03:08] - pre-processing segment 2/2 contentName!=xx
INFO [2015-08-31 07:03:11] Archived website id = 1, period = day, 2 segments, 0 visits in last last52 days, 0 visits today, Time elapsed: 2.810s

I would expect 07:03:11 - 07:03:06 = 4 or 5 seconds, got: Time elapsed: 2.810s - the counter being used is the wrong one

@tsteur
Copy link
Member

tsteur commented Aug 31, 2015

There are three different timers. Total timer, Website timer and I'd name it "period timer". It took 2.8 seconds to archive that period and it should be correct, there were possibly 1-2 seconds spent on general website related archiving stuff but one cannot really assign it to a special period. I know it's weird that it says - pre-processing all visits at 03:06 and it looks like the timer is initiated too late there. I will issue a PR that might fix it but I'm not sure. In the meantime I prepared and threw away 3 replies to this... the code is a mess and it's not really possible to understand all this.

@tsteur
Copy link
Member

tsteur commented Aug 31, 2015

As PR was merged we can close this as well?

@mattab mattab closed this as completed Aug 31, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug For errors / faults / flaws / inconsistencies etc.
Projects
None yet
Development

No branches or pull requests

4 participants