Resolve high CPU usage when performing DB reads #419

abraunegg · 2019-03-19T19:15:37Z

Disable automatic indexing (enabled by default in sqlite as of version 3.7.17) as we specifically create the required indexes
Tell SQLite to store temporary tables in memory. This will speed up many read operations that rely on temporary tables, indices, and views.

Resolves issues:
#21, #347, #394, #404, #432 (in part, as full file system scanning is still occuring which is being looked at in #433)

* Disable automatic indexing as we specifically create the required indexes

* Tell SQLite to store temporary tables in memory. This will speed up many read operations that rely on temporary tables, indices, and views. * Add links & reasoning behind other PRAGMA settings used

* Add new index specifically for driveId & parentId paring

abraunegg · 2019-03-21T10:17:10Z

@norbusan
Based on user feedback, it would appear that the latest commit does fix the issue.

Question is - how to 'fix' this properly?

The easiest way potentially would be to 'revision' the database internal counter, as, when I was coding all the CentOS / Fedora fixes, to overcome the DB issues, if the DB version was < X it would re-create the tables & database.

Worth testing this increment to resolve this situation as well? Potentially it 'should' but I do not know if the index's would still be hanging around / would get auto created correctly - would need complete testing.

norbusan · 2019-03-21T10:41:10Z

Yes, that is probably the best idea. In shotwell (photo editor) where I also contribute(d), there is a database table version saved in the DB, and the program compares and does some update routines depending on the version.

So asssume we are at version 1 now, and bump it in the program to version 2. On next run the program sees that the saved DB is actually version 1, and does add the index and updates the version saved in the database.

That works nicely.

In this case, I am not sure if calling the create index on every database open sounds like calling for problems? I don't know what sqlite is doing in case there is already an index.

* To force DB schema & index creation, bump DB schema version

abraunegg · 2019-03-21T17:41:52Z

@norbusan
Updated the DB version:

Loading config ...
Using Config Dir: /home/alex/.config/onedrive
No config file found, using application defaults
Initializing the OneDrive API ...
Opening the item database ...
The item database is incompatible, re-creating database table structures
All operations will be performed in: /home/alex/OneDrive
Initializing the Synchronization Engine ...
Account Type: personal
Default Drive ID: 66d53be8a5056eca
Default Root ID: 66D53BE8A5056ECA!101
Remaining Free Space: 4821211072
Fetching details for OneDrive Root
OneDrive Root does not exist in the database. We need to add it.
Added OneDrive Root to the local database
Initializing monitor ...
OneDrive monitor interval (seconds): 45

When this gets pushed into Master, everyone's DB will get updated to support the new index

* Update handling of skip_dir and skip_file parsing - should only check if the file is excluded if the parent directory is not * Add another index for selectByPath database queries

* New build option to get more DEBUG symbolic information

* Update ldc2 debug handling

* Use boolean values rather than on / off values * Enable auto_vacuum for entry deletes / database cleanup

norbusan · 2019-03-23T23:44:12Z

@abraunegg I am for merging this, it has shown its use already and fixed several participants problems.

abraunegg · 2019-03-24T00:11:33Z

Agreed - merging

rednag · 2019-03-24T19:39:19Z

I don't see that this/my issue is fixed, because in 45s interval my CPU is 30s on 100% with onedrive v2.2.6-21-ga9795dd, or I do something wrong? :/

abraunegg · 2019-03-24T19:44:57Z

@rednag
Please can you have a read of #433 and confirm your issue of 100% CPU load is only occuring when the full file system scan is occuring?

If not - please 'delete' the items database file and test / try again.

Also, as this code is merged into master, with v2.3.0 pending - please ensure you rebuild your client from 'master'

rednag · 2019-03-24T20:15:31Z

So every 45s is a full file system scan? In CPU history it looks like that. I do not upload or change anything and have every 45s around 30s 100% CPU usage.

I've deleted the files and test it again, but I always deleted the database items.

edit1:
Same behavior and always the same curve in CPU history.

You see, the cycle of 45s and it is pretty much the same curve.

edit2:
Restarted again with rebuild and deletion. While

Mär 24 21:29:20 CX onedrive[5399]: Processing 203 changes
Mär 24 21:29:22 CX onedrive[5399]: Processing 218 changes
Mär 24 21:29:23 CX onedrive[5399]: Processing 218 changes
Mär 24 21:29:25 CX onedrive[5399]: Processing 246 changes
Mär 24 21:29:27 CX onedrive[5399]: Processing 212 changes
Mär 24 21:29:29 CX onedrive[5399]: Processing 234 changes
Mär 24 21:29:31 CX onedrive[5399]: Processing 231 changes
Mär 24 21:29:33 CX onedrive[5399]: Processing 211 changes

There is no high CPU usage!

So while processing is less CPU usage than while monitoring?! So processing is finished an we have the 45s cycle with 100% CPU usage!

Mär 24 21:35:38 CX onedrive[5399]: Processing JHPSAEM7E2QSZJ7ORDIPHTRXH5T5SINF
Mär 24 21:35:38 CX onedrive[5399]: The file has not changed
Mär 24 21:35:38 CX onedrive[5399]: Processing L3TKSR7EEL3XII6GNRX4EXD2I2NHRCXS
Mär 24 21:35:38 CX onedrive[5399]: The file has not changed
Mär 24 21:35:38 CX onedrive[5399]: Processing BAOS7CWJ2KVRWABOMTT7TZN3JMVDOSLG
Mär 24 21:35:38 CX onedrive[5399]: The file has not changed
Mär 24 21:35:38 CX onedrive[5399]: Processing 4SIW5KD6YVZWISRAQCJVKQ5JYSMSWMRC
Mär 24 21:35:38 CX onedrive[5399]: The file has not changed
Mär 24 21:35:38 CX onedrive[5399]: Processing NP6KKUPTEVFIWG7RU3GUMZPCYCJODDST
Mär 24 21:35:38 CX onedrive[5399]: The file has not changed

abraunegg · 2019-03-24T20:49:02Z

@rednag

Mär 24 21:29:33 CX onedrive[5399]: Processing 211 changes

This is 'database' re-creation - taking OneDrive JSON data and processing it.

Mär 24 21:35:38 CX onedrive[5399]: Processing JHPSAEM7E2QSZJ7ORDIPHTRXH5T5SINF

This is scanning the database / validating the contents

At the end of this sequence, you will see:

Uploading new items of .

This is where the client is now performing a 'walk' of your sync_dir to ensure that all files / folders are actually uploaded.

This is where your 100% load is most likely coming from now. This is currently normal application behaviour.

So you have a couple of options:

Change the 45 second sync window via your config file
Wait for the changes in Reduce scanning of local filesystem needlessly every sync in monitor mode #433 to drop in v2.3.1 - however periodically the application will still scan the entire path which will cause CPU load.

If you are still having issues, please:

Open a new issue ticket
Provide debug data - perf data output & strace

rednag · 2019-03-25T05:40:14Z

Thank you for your support :), how long does this sequence take

Mär 25 06:38:34 CX onedrive[5399]: Processing JHPSAEM7E2QSZJ7ORDIPHTRXH5T5SINF
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed
Mär 25 06:38:34 CX onedrive[5399]: Processing L3TKSR7EEL3XII6GNRX4EXD2I2NHRCXS
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed
Mär 25 06:38:34 CX onedrive[5399]: Processing BAOS7CWJ2KVRWABOMTT7TZN3JMVDOSLG
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed
Mär 25 06:38:34 CX onedrive[5399]: Processing 4SIW5KD6YVZWISRAQCJVKQ5JYSMSWMRC
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed
Mär 25 06:38:34 CX onedrive[5399]: Processing NP6KKUPTEVFIWG7RU3GUMZPCYCJODDST
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed

Then it is still validating?!

abraunegg · 2019-03-25T05:54:34Z

Thank you for your support :), how long does this sequence take

Mär 25 06:38:34 CX onedrive[5399]: Processing JHPSAEM7E2QSZJ7ORDIPHTRXH5T5SINF
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed
Mär 25 06:38:34 CX onedrive[5399]: Processing L3TKSR7EEL3XII6GNRX4EXD2I2NHRCXS
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed
Mär 25 06:38:34 CX onedrive[5399]: Processing BAOS7CWJ2KVRWABOMTT7TZN3JMVDOSLG
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed
Mär 25 06:38:34 CX onedrive[5399]: Processing 4SIW5KD6YVZWISRAQCJVKQ5JYSMSWMRC
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed
Mär 25 06:38:34 CX onedrive[5399]: Processing NP6KKUPTEVFIWG7RU3GUMZPCYCJODDST
Mär 25 06:38:34 CX onedrive[5399]: The file has not changed

Then it is still validating?!

That is the DB validation sequence. There should be little to moderate CPU load depending on the number of files within the local database.

Prior to this PR , a DB index was missing, thus causing excessive CPU.

How long should that process take? It depends on many factors - CPU speed, memory speed, disk I/O ...

rednag · 2019-03-25T05:55:48Z

After 9h it is still validating and there is high CPU usage as well with the 2.3.

Maybe there is a better way to recognize changes, instead to monitor all files?! Isn't it possible to observe opened files in a path and just sync or monitor if files opened in the OneDrive directory?!

abraunegg · 2019-03-25T06:13:29Z

@rednag
I think you have something else going on where the disk I/O is hindering you - again, looking at the SD card.

abraunegg · 2019-03-25T06:16:01Z

@rednag
I am currently out of options as to what else it can be. Unless you can provide a real deep dive analysis of all the processes / stack traces etc of everything, it is very hard to say what your issue is.

I would even go so far to test your system / setup without using Ubuntu - use a pure Debian or CentOS or Arch Linux.

abraunegg · 2019-03-25T06:38:28Z

@norbusan
Open to also any suggestions you may have here ...

norbusan · 2019-03-25T06:40:58Z

sorry, I run out of ideas. Something is really strange on that computer. Either file reads are slow, or other processes are hogging IO, or whatever. But without actually sitting in front of the system I don't see a good way to debug this.

rednag · 2019-03-25T07:05:04Z

edit:
I've switched the interval from 45s to 300s and now there are all problems gone?!

lock · 2019-04-26T19:20:58Z

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

abraunegg added 2 commits March 20, 2019 06:13

Update itemdb.d

2b1c767

* Disable automatic indexing as we specifically create the required indexes

Update itemdb.d

eeeeb9a

* Tell SQLite to store temporary tables in memory. This will speed up many read operations that rely on temporary tables, indices, and views. * Add links & reasoning behind other PRAGMA settings used

abraunegg mentioned this pull request Mar 20, 2019

High CPU usage when validating sync state #404

Closed

3 tasks

Update itemdb.d

2701434

* Add new index specifically for driveId & parentId paring

abraunegg added this to the 2.3.0 milestone Mar 21, 2019

abraunegg added 2 commits March 22, 2019 04:30

Merge branch 'master' into high-cpu-usage-db-query

66bac01

Update itemdb.d

082d632

* To force DB schema & index creation, bump DB schema version

abraunegg mentioned this pull request Mar 21, 2019

2nd Random crash when attempting to upload 50K files #425

Closed

norbusan previously approved these changes Mar 21, 2019

View reviewed changes

abraunegg changed the title ~~WIP: Resolve high CPU usage when performing DB reads~~ Resolve high CPU usage when performing DB reads Mar 22, 2019

abraunegg added 2 commits March 23, 2019 06:34

Merge branch 'master' into high-cpu-usage-db-query

d43999d

Add selectByPath DB index

ef22579

* Update handling of skip_dir and skip_file parsing - should only check if the file is excluded if the parent directory is not * Add another index for selectByPath database queries

abraunegg dismissed norbusan’s stale review via ef22579 March 22, 2019 20:24

asnowfix and others added 3 commits March 24, 2019 06:40

New build option to get more DEBUG symbolic information (#421)

e1d5cfe

* New build option to get more DEBUG symbolic information

Update Makefile

d8ebfe7

* Update ldc2 debug handling

Update itemdb.d

a9795dd

* Use boolean values rather than on / off values * Enable auto_vacuum for entry deletes / database cleanup

norbusan approved these changes Mar 23, 2019

View reviewed changes

abraunegg merged commit 79cc599 into master Mar 24, 2019

abraunegg deleted the high-cpu-usage-db-query branch March 24, 2019 02:39

abraunegg mentioned this pull request Apr 24, 2019

CPU running at 100 percent non-stop skilion/onedrive#373

Closed

lock bot locked and limited conversation to collaborators Apr 26, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Resolve high CPU usage when performing DB reads #419

Resolve high CPU usage when performing DB reads #419

abraunegg commented Mar 19, 2019 •

edited

Loading

abraunegg commented Mar 21, 2019

norbusan commented Mar 21, 2019

abraunegg commented Mar 21, 2019

norbusan commented Mar 23, 2019

abraunegg commented Mar 24, 2019

rednag commented Mar 24, 2019

abraunegg commented Mar 24, 2019

rednag commented Mar 24, 2019 •

edited

Loading

abraunegg commented Mar 24, 2019 •

edited

Loading

rednag commented Mar 25, 2019 •

edited

Loading

abraunegg commented Mar 25, 2019

rednag commented Mar 25, 2019 •

edited

Loading

abraunegg commented Mar 25, 2019

abraunegg commented Mar 25, 2019

abraunegg commented Mar 25, 2019

norbusan commented Mar 25, 2019

rednag commented Mar 25, 2019 •

edited

Loading

lock bot commented Apr 26, 2019

Resolve high CPU usage when performing DB reads #419

Resolve high CPU usage when performing DB reads #419

Conversation

abraunegg commented Mar 19, 2019 • edited Loading

abraunegg commented Mar 21, 2019

norbusan commented Mar 21, 2019

abraunegg commented Mar 21, 2019

norbusan commented Mar 23, 2019

abraunegg commented Mar 24, 2019

rednag commented Mar 24, 2019

abraunegg commented Mar 24, 2019

rednag commented Mar 24, 2019 • edited Loading

abraunegg commented Mar 24, 2019 • edited Loading

rednag commented Mar 25, 2019 • edited Loading

abraunegg commented Mar 25, 2019

rednag commented Mar 25, 2019 • edited Loading

abraunegg commented Mar 25, 2019

abraunegg commented Mar 25, 2019

abraunegg commented Mar 25, 2019

norbusan commented Mar 25, 2019

rednag commented Mar 25, 2019 • edited Loading

lock bot commented Apr 26, 2019

abraunegg commented Mar 19, 2019 •

edited

Loading

rednag commented Mar 24, 2019 •

edited

Loading

abraunegg commented Mar 24, 2019 •

edited

Loading

rednag commented Mar 25, 2019 •

edited

Loading

rednag commented Mar 25, 2019 •

edited

Loading

rednag commented Mar 25, 2019 •

edited

Loading