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

Comments

Projects
None yet
4 participants
@mattab
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 label Aug 21, 2015

@mattab mattab added this to the 2.15.0 milestone Aug 21, 2015

@quba

This comment has been minimized.

Show comment
Hide comment
@quba

quba Aug 21, 2015

Contributor

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.

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

This comment has been minimized.

Show comment
Hide comment
@tsteur

tsteur Aug 24, 2015

Member

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

Member

tsteur commented Aug 24, 2015

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

@mnapoli

This comment has been minimized.

Show comment
Hide comment
@mnapoli

mnapoli Aug 24, 2015

Contributor

Got valid numbers:

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

Contributor

mnapoli commented Aug 24, 2015

Got valid numbers:

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

@tsteur tsteur self-assigned this Aug 29, 2015

tsteur added a commit that referenced this issue Aug 29, 2015

@tsteur

This comment has been minimized.

Show comment
Hide comment
@tsteur

tsteur Aug 31, 2015

Member

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?

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

This comment has been minimized.

Show comment
Hide comment
@mattab

mattab Aug 31, 2015

Member

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

Member

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

This comment has been minimized.

Show comment
Hide comment
@tsteur

tsteur Aug 31, 2015

Member

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.

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

This comment has been minimized.

Show comment
Hide comment
@tsteur

tsteur Aug 31, 2015

Member

As PR was merged we can close this as well?

Member

tsteur commented Aug 31, 2015

As PR was merged we can close this as well?

@mattab mattab closed this Aug 31, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment