New collumn of execution time added in db schema of oc_jobs #27144

Merged
merged 17 commits into from Feb 23, 2017

Projects

None yet

7 participants

@noveens
Contributor
noveens commented Feb 12, 2017 edited

Description

I have changed the schema of the db_structure.xml file and the corresponding tests where oc_jobs was concerned.

I added a column of execution duration in the oc_jobs table.

Related Issue

#27137

Motivation and Context

This is a new feature which could help in testing of the system.

How Has This Been Tested?

I have tested this thoroughly, even edited one of the tests because of the database migration.

Screenshots (if appropriate):

Not necessary.

Types of changes

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality to change)

Checklist:

  • My code follows the code style of this project.
  • My change requires a change to the documentation.
  • I have updated the documentation accordingly.
  • I have read the CONTRIBUTING document.
  • I have added tests to cover my changes.
  • All new and existing tests passed.
@noveens noveens New collumn of execution time added in db schema of oc_jobs
050f031
@mention-bot

@noveens, thanks for your PR! By analyzing the history of the files in this pull request, we identified @bantu, @tanghus and @butonic to be potential reviewers.

@CLAassistant
CLAassistant commented Feb 12, 2017 edited

CLA assistant check
All committers have signed the CLA.

@PVince81
Collaborator

This will likely not be enough.

In past ownCloud versions, the XML file was the authority regarding database schemas.
Since master / 10.0, we should use migrations to make database changes.

Have a look how it's done here: https://github.com/owncloud/core/blob/master/core/Migrations/Version20170111103310.php#L9.
Some docs about migrations: owncloud/documentation#2742 (unfinished as this is brand new).

Let me know if you need assistance.

Once this is done the next step is to adjust the background job runner to measure the execution time and put it there.

@noveens
Contributor
noveens commented Feb 13, 2017

@PVince81 , thanks for the quick review, I'll look into it as soon as possible.
Thanks for the links to ducumentation as well.

noveens added some commits Feb 13, 2017
@noveens noveens Finally completed adding a column to oc_jobs through migration.
4a4fbb5
@noveens noveens trailing space.
c86fa8a
@noveens
Contributor
noveens commented Feb 13, 2017

@PVince81 , please check now, I completed making another column in oc_jobs table named execution time through migration.

tests/lib/DB/schemDiffData/core.xml
@@ -732,6 +732,14 @@
<notnull>false</notnull>
</field>
+ <field>
tests/lib/DB/schemDiffData/unsigned.xml
@@ -61,6 +61,14 @@
<notnull>false</notnull>
</field>
+ <field>
@noveens
noveens Feb 13, 2017 edited Contributor

@DeepDiver1975 ,
So I shouldn't add the new column of execution_duration in oc_jobs table's schema of the tests?

@DeepDiver1975
DeepDiver1975 Feb 13, 2017 Member

no this is not necessary

@noveens
noveens Feb 13, 2017 Contributor

removing it.

@noveens noveens Tests updation not required.
fab44e2
@DeepDiver1975
Member

@noveens THx - next would be to fill the columns 😉

@noveens
Contributor
noveens commented Feb 13, 2017

@DeepDiver1975 , does that come in the scope of this bug?

@PVince81
Collaborator

@noveens yes, because else the column is completely useless.

Do you need pointers ?

@noveens
Contributor
noveens commented Feb 14, 2017

@PVince81, pointers would be a great way to start.

@PVince81
Collaborator

Pointers

The job is executed here: https://github.com/owncloud/core/blob/master/cron.php#L122

I suggest you add statements around here https://github.com/owncloud/core/blob/master/lib/private/BackgroundJob/Job.php#L52 to measure the running time. Then store the value in the database.

For storing, use something like https://github.com/owncloud/core/blob/master/lib/private/BackgroundJob/JobList.php#L307. Maybe a new method setLastRunTime().

@noveens
Contributor
noveens commented Feb 14, 2017 edited

@PVince81 , I have made the new method, but how to check the changes I have made?

Update: Pushed the changes I made, please review @DeepDiver1975

@noveens noveens New method added to store execution duration in oc_jobs
108444d
lib/private/BackgroundJob/JobList.php
+ public function setExecutionTime($job, $timeTaken) {
+ $query = $this->connection->getQueryBuilder();
+ $query->update('jobs')
+ ->set('last_run', $query->createNamedParameter($timeTaken, IQueryBuilder::PARAM_INT))
@PVince81
PVince81 Feb 14, 2017 Collaborator

wrong column ?

@noveens
noveens Feb 14, 2017 Contributor

sorry, bad mistake :p

@noveens
noveens Feb 14, 2017 Contributor

@PVince81 , updated

@PVince81
Collaborator

@noveens please have a look at my comment.

To test this you can run php cron.php manually.
If no job is running because of the schedule, you can reset the jobs manually with the following SQL query:

update oc_jobs set last_run=0,last_checked=0,reserved_at=0;

Then run cron.php again and see if your new column is populated.

@noveens noveens wrong column fixed
7ca8316
@noveens
Contributor
noveens commented Feb 14, 2017

@PVince81 , please recheck

@PVince81
Collaborator

Code looks good so far. Thanks.

Will test it later.

@PVince81
Collaborator

I tested it but after running cron.php I see the last_run being populated, but the value of "execution_duration" is always 0.

Even if my computer is too fast, I'd still expect values of at least a few millisecond.
Is that timestamp in seconds ?

Wanted to test it with LDAP (which provides ways to have slower jobs) but the app is broken at the moment: #27154

@noveens
Contributor
noveens commented Feb 14, 2017 edited

@PVince81 ,
The new column I have added is of integer type since the time() function gives seconds since epoch
But the general case of checking working time of a job has time lesser than 1 second.

Hence I chose this approach.
If you need any updation, please tell me.

@PVince81
Collaborator
  • increase last digit in version.php to trigger an update
@PVince81
Collaborator

Tested with LDAP. I saw cron.php taking a minute or so, still the column "execution_duration" contains only zeroes.

How did you test it?

@noveens
Contributor
noveens commented Feb 15, 2017

@PVince81 ,
To be frank, I didn't test it because I couldn't find a way to populate the database.
Also, once populated how should I check the values in the database?

It would be great if you could tell me how to test this.

@PVince81
Collaborator

Told you here: #27144 (comment)

The table is already pre-populated by default recurring jobs after setting up OC.

@noveens noveens called setExecutionTime at wrong place, fixed now.
6929f81
@noveens
Contributor
noveens commented Feb 15, 2017 edited

@PVince81 @DeepDiver1975 ,
Everything is fixed now, after lot of research and mind-breaking, my mistake was :
I was calling setExecutionTime from the wrong class (had to be called from Job class rather than JobList class).

Please Recheck.

@PVince81
Collaborator

Okay cool, it seems to work now.

I wonder if we should use millisecond values here to avoid having misleading zeroes in the column.

Thoughts ? @dercorn @jvillafanez @butonic @DeepDiver1975

@noveens
Contributor
noveens commented Feb 16, 2017

@PVince81 ,
I think we can use gettimeofday( ) to get the execution time in the precision of even microseconds, though milli is better (considering overflow problems).
Should I change the code to store milliseconds rather than seconds?

@jvillafanez
Contributor

Please, include a log in the Job.php file. This will help to track the request id of the job and know what it's doing. Something like:

public function execute($jobList, ILogger $logger = null) {
  $jobList->setLastRun($this);
  try {
    $t1 = time();
    \OCP\Util::writeLog('jobs', 'Started background job ' . get_class($this) . print_r($this->argument, true), \OCP\Util::DEBUG);
      $this->run($this->argument);
    $secs = time() - $t1;
    \OCP\Util::writeLog('jobs', "Finished background job $secs seconds " . get_class($this) . print_r($this->argument, true), \OCP\Util::DEBUG);
  } catch (\Exception $e) {

So

  • A log there is important. This will help to distinguish what log entries come from the background job. It's your choice if you want to wrap the run method in a "start" and "finish" logs.
  • Logging the class with get_class($this) is important. This will allow to match the request id with the specific job, which will make easy to track down what the specific job is doing.
  • Logging the arguments isn't really needed. I'm not sure if there is a job that uses a password, and not sure if the password will leak. In case of doubt, just ignore the arguments and stay safe.
@jvillafanez
Contributor

I wonder if we should use millisecond values here to avoid having misleading zeroes in the column.

I don't think it's needed. If we need a default value to know what jobs haven't run already, just use null or -1, and let 0 be a valid value. We don't need such precision because we're interested in long running jobs.

@noveens
Contributor
noveens commented Feb 16, 2017

@jvillafanez ,
I like the method of having a default value of -1.
I'll implement it.

I'll research more about the log part and get back if required.

@noveens
Contributor
noveens commented Feb 16, 2017

@jvillafanez , I'll implement the log part as well

Updating changes in 10 mins.

@noveens noveens default value of execution time set to -1, logging enabled.
9fe7a85
@noveens
Contributor
noveens commented Feb 16, 2017

@jvillafanez @PVince81 @DeepDiver1975 ,
Please review this PR since it seems it's okay to me now.

lib/private/BackgroundJob/Job.php
+ //storing job start time
+ $jobStartTime = time();
+
+ \OCP\Util::writeLog('jobs', 'Started background job ' . get_class($this) . print_r($this->argument, true), \OCP\Util::DEBUG);
@jvillafanez
jvillafanez Feb 16, 2017 Contributor
'Started background job ' . get_class($this) . ' : ' . json_encode($this->argument)

it seems a nicer message.

lib/private/BackgroundJob/Job.php
+ $jobEndTime = time();
+ $timeTaken = $jobEndTime - $jobStartTime;
+
+ \OCP\Util::writeLog('jobs', "Finished background job $timeTaken seconds " . get_class($this) . print_r($this->argument, true), \OCP\Util::DEBUG);
@jvillafanez
jvillafanez Feb 16, 2017 Contributor
'Finished background job ' . get_class($this) . ' : ' . json_encode($this->argument) . " (it took $timeTaken seconds)"

nicer message

@PVince81
PVince81 Feb 16, 2017 Collaborator

also change the app name to "cron", not "jobs".

@jvillafanez
Contributor

I don't have experience with migrations, but code looks good.

@PVince81
Collaborator

Apart from the cron message this looks good.

@noveens noveens Logging messages changed
04e7a46
@noveens
Contributor
noveens commented Feb 16, 2017

@bantu, @tanghus, @butonic, @DeepDiver1975 and @PVince81 ,

Please check the code, I think bug's solved now.

@jvillafanez
Contributor
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Run OCA\\Files_Sharing\\DeleteOrphanedSharesJob job with ID 12","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Finished OCA\\Files_Sharing\\DeleteOrphanedSharesJob job with ID 12","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Run OCA\\Files_Sharing\\ExpireSharesJob job with ID 13","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Finished OCA\\Files_Sharing\\ExpireSharesJob job with ID 13","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Run OC\\Authentication\\Token\\DefaultTokenCleanupJob job with ID 14","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Started background job of class : OC\\Authentication\\Token\\DefaultTokenCleanupJob","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"no app in context","message":"Invalidating tokens older than 2017-02-16T07:47:28+00:00","level":1,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Finished background job, the job took : 0 seconds\njob is an instance of class : OC\\Authentication\\Token\\DefaultTokenCleanupJob","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Finished OC\\Authentication\\Token\\DefaultTokenCleanupJob job with ID 14","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Run OCA\\User_LDAP\\Jobs\\UpdateGroups job with ID 15","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}
{"reqId":"fpgDDP2MArnPXZMA\/Ni+","remoteAddr":"","app":"cron","message":"Finished OCA\\User_LDAP\\Jobs\\UpdateGroups job with ID 15","level":0,"time":"2017-02-17T07:47:28+00:00","method":"--","url":"--","user":"--"}

A couple of things taking into account from the logs:

  • The PHP_EOL should be removed. Each log entry will be in one line, so any newline char is an unwanted addition.
  • You've put get_class($this) . print_r($this->argument, true). There is no space between both the get class and the print_r, so the output might be confusing.
  • For now, I haven't seen any output for the print_r($this->argument, true). I'm not sure how the log will look like. @noveens if you've tested it, please show a couple of outputs: one with the print_r and another one with the json_encode, so we can check what format is more useful for the admin. (I'm not requesting any change for this at the moment).

Aside from this, we have another problem as you can see in the log output: duplicated and also false messages.

Those logs come from https://github.com/owncloud/core/blob/master/cron.php#L121 , and duplicate the new logs.

In addition, timed jobs can skip their own execution (https://github.com/owncloud/core/blob/master/lib/private/BackgroundJob/TimedJob.php#L52-L54), so the "Run blablabla job with ID 13" message could be a lie because the job can be skipped.

Taking this into account, I think we should include the removal of those message and stick with the new logs because they're more accurate.

@noveens noveens logging messages format changed
1f269a9
@noveens
Contributor
noveens commented Feb 17, 2017 edited

@jvillafanez ,

As requested, I have deleted the log statements from : https://github.com/owncloud/core/blob/master/cron.php#L121

Plus, Even I didn't find print_r($this->argument, true) print anything but IMO we should leave it so that if we have some arguments in future, it would print them.

Small changes requested in logging messages also have been changed,

lib/private/BackgroundJob/Job.php
+ //storing job start time
+ $jobStartTime = time();
+
+ echo 'some' . PHP_EOL;
@jvillafanez
jvillafanez Feb 17, 2017 Contributor

remove this echo and the gettype below

@noveens
noveens Feb 17, 2017 Contributor

sorry, forgot to remove the debug statements.

Updated changes pushed.

@jvillafanez
Contributor

I think we're almost there. We'll have to check how it behaves and check if there is any additional unexpected consecuence.

From my point of view, just fix the comment above, and then it's ready for testing.

@noveens noveens debug statements removed
02659b1
@jvillafanez
Contributor

@PVince81 @DeepDiver1975 I had to manually increase the OC version to force the trigger of the migration code (checked against daily master). I guess this will be fine once the code is merged. It's just to confirm that no more changes are needed.

Calling @owncloud/qa ....

Things to check ( @noveens feel free to add anything that has to be checked and I might be missing)

  • New column "execution_time" in the "jobs" table with a default value of -1
  • Running cron will:
    • set the execution time in seconds of the job in the "jobs" table. 0 is a valid value. It will help to identify what jobs have run and what jobs not.
    • add new logs entries in the owncloud.log. The logs entries should be clear enough to know what jobs have run, and should match the information contained in the "jobs" table.
  • Need to test against a "heavy" system to verify we're counting the seconds right and not just setting zeros. Probably testing with LDAP active is enough to have some slow jobs which should take more than 1 second to execute.
  • Find a job with arguments and check the log output.

Jenkins is complaining.... we'll need to check what happens with the tests.

@noveens
Contributor
noveens commented Feb 17, 2017

@jvillafanez ,
the column name is "execution_duration", rest everything seems fine to me.

noveens added some commits Feb 17, 2017
@noveens noveens tests updated for oc_jobs
bd87953
@noveens noveens defination of setExecutionTime() added in public.
008f78a
@noveens noveens trying to pass jenkins
c43ed8c
@noveens noveens trying to pass jenkins
b394ec6
@noveens noveens trying to pass jenkins
8b6dc6d
@noveens
Contributor
noveens commented Feb 17, 2017

@bantu, @tanghus, @butonic, @DeepDiver1975 and @PVince81 ,

I managed to pass Jenkins now ( took 1h 42m :p ) please have a look and review this PR.

@jvillafanez
Contributor

Revert the permission change in the config.sample.php file please.

@davitol
Contributor
davitol commented Feb 20, 2017 edited

I had to manually increase the OC version to force the trigger of the migration code (checked against daily master).

I tested the PR in the same way.

New column "execution_time" in the "jobs" table with a default value of -1
Running cron will:

set the execution time in seconds of the job in the "jobs" table. 0 is a valid value. It will help to identify what jobs have run and what jobs not. ✅ 
add new logs entries in the owncloud.log. The logs entries should be clear enough to know what jobs have run, and should match the information contained in the "jobs" table.


Need to test against a "heavy" system to verify we're counting the seconds right and not just setting zeros. Probably testing with LDAP active is enough to have some slow jobs which should take more than 1 second to execute.
Find a job with arguments and check the log output.

👍

IMHO A small enhancement when running a job without arguments will be to not print the with arguments: text

{"reqId":"4vkT2Z8Fy\/yzBApDPlqT","remoteAddr":"","app":"cron","message":"Finished background job, the job took : 0 seconds, this job is an instance of class : OCA\\Files\\BackgroundJob\\CleanupFileLocks with arguments : ","level":0,"time":"2017-02-20T12:08:15+00:00","method":"--","url":"--","user":"--"}
@noveens
Contributor
noveens commented Feb 20, 2017

@jvillafanez ,
I didn't get the part I have to change,
you're talking about which permissions?

@jvillafanez
Contributor

screen shot 2017-02-21 at 09 05 54

That change in the permissions of the config.sample.php . It shouldn't appear.

@PVince81 PVince81 added this to the 10.0 milestone Feb 21, 2017
@noveens noveens config.sample.php permissions changed
7cd78c6
@noveens
Contributor
noveens commented Feb 21, 2017

@jvillafanez ,
pushed the changes.

@noveens
Contributor
noveens commented Feb 21, 2017

@DeepDiver1975 ,
please re-review this

@jvillafanez
Contributor

I don't have anything more to add 👍

@noveens
Contributor
noveens commented Feb 23, 2017

@PVince81 ,
Can this be merged, I think it's fine now.

@PVince81
Collaborator

@DeepDiver1975 can you kick Jenkins to retest this ?

@noveens
Contributor
noveens commented Feb 23, 2017

@PVince81 ,
This passed jenkins before my previous commit, which was just modifying the file permissions of config.sample.php which i suppose has nothing to do with any of the tests.

@PVince81 PVince81 merged commit ea59b53 into owncloud:master Feb 23, 2017

3 of 4 checks passed

continuous-integration/jenkins/pr-head This commit cannot be built
Details
Scrutinizer 1849 Issues, 149 Patches
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
licence/cla Contributor License Agreement is signed.
Details
@PVince81
Collaborator

Added to new features page: https://github.com/owncloud/core/wiki/ownCloud-10.0-Features

@jvillafanez
Contributor

@PVince81 @DeepDiver1975 Backport the logging part? I think it could be quite useful and not intrusive. DB changes won't be backported.

@PVince81
Collaborator

Yes, please backport the logging part.

@noveens can you do it ? Basically create a branch off "stable9.1", put your commits there then submit a PR that targets stable9.1. Only put the logging part there.

@noveens
Contributor
noveens commented Feb 23, 2017

@PVince81 ,
Sure I can do that.
Just the logging part right?
And do I have to update anything in this branch?

@PVince81
Collaborator

Nothing to update here. Make a new branch.

@noveens noveens added a commit to noveens/core that referenced this pull request Feb 23, 2017
@noveens noveens backporting logging changes of PR #27144 75df4ea
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment