[OSX] CPU usage #2990

stonerl · 2015-03-20T14:07:12Z

While using the Activity Monitor I just observed that ownCloud sometimes kicked in with a CPU usage of round about 50%. So I traced the behavior with Xcode and there I could see that every 30 seconds ownCloud uses allot of CPU for about 3 seconds. After 20 minutes the total CPU Time was: 1:11.70125. In comparison, dropbox was started a mere second before ownCloud and at the end of my measurement had a CPU Time of only 8.911494.

I uploaded the tracefile to my server, if needed you can find it here:

https://kumori.fosuta.org/public.php?service=files&t=611b8b351a755e965f824fda08ffddad

I don't know if this is anyhow related to #2937

danimo · 2015-03-20T14:08:10Z

@stonerl which version did you use?

stonerl · 2015-03-20T14:09:04Z

Sorry I just forgot to tell. 1.8.0 (Build 2139)

guruz · 2015-03-23T09:54:08Z

Do you use any specific external storage on your server?

stonerl · 2015-03-23T10:25:12Z

@guruz No, just a plain vServer with:

4GB RAM
240 GB HDD
Ubuntu 14.04.2 LTS
Apache/2.4.7
ownCloud 7.0.4

And if needed, my Client Specs:

MacBook (13-inch, Mid 2010)
2,4 GHz Intel Core 2 Duo
16 GB RAM
OS X 10.10.2 (14C1514)

stonerl · 2015-03-23T11:19:15Z

I think I figured out where the cpu usage comes from. I don't use one ownCloud folder to sync, I have configured four: Documents, Videos, Music, Pictures. After I removed three of the them from sync, the CPU Time after 20 Minutes where only 23 seconds. I'm going to test this further, but so far the more folders are configured the more cpu is used.

stonerl · 2015-03-23T11:58:19Z

So it is as I suspected. I returned to my usual configuration with 6 folders and CPU Time went up to 2 minutes after 20 minutes. So as I stated before, the more folders are configured, the higher the CPU usage.

stonerl · 2015-03-23T12:46:49Z

btw. maybe this one here is related #2993.

guruz · 2015-03-23T15:51:08Z

@stonerl I think the logfile could help here to find out what re-triggers the sync to be launched https://raw.githubusercontent.com/owncloud/client/master/issue_template.md

stonerl · 2015-03-23T16:15:06Z

@guruz the logfile can be found here:

https://kumori.fosuta.org/public.php?service=files&t=837aa204dfc0f0b0d332b03aa39764ef

I ran ownCloud for about 5 minutes.

guruz · 2015-03-23T16:39:24Z

In your log I can see the last
03-23 17:05:45:410 0x7fa24355aab0 OCC::Folder::slotSyncFinished: -> SyncEngine finished without problem. at that time stamp.
From then to end of file (17:10:12) no more sync is happening..

I wonder what would then use the CPU? I don't see anything in the log which would cause a lot of CPU.

CC @ckamm @jturcotte

stonerl · 2015-03-23T17:22:37Z

I just traced ownclout once again and looked in the logfile. As I said before the high cpu usage appears every 30 seconds so I think it gets invoked with this:

03-23 18:14:03:606 0x600000017fb0 OCC::FolderMan::slotEtagPollTimerTimeout: void OCC::FolderMan::slotEtagPollTimerTimeout() The following folders need to check for the remote ETag: QSet("Android", "Movies", "Music", "Documents")

03-23 18:14:33:605 0x600000017fb0 OCC::FolderMan::slotEtagPollTimerTimeout: void OCC::FolderMan::slotEtagPollTimerTimeout() The following folders need to check for the remote ETag: QSet("Projects", "Android", "Movies", "Music", "Documents")

guruz · 2015-03-25T08:01:19Z

Could I ask you to try this nightly build: http://download.owncloud.com/desktop/daily/ownCloud-1.8.0.2204-nightly20150325.pkg ?

stonerl · 2015-03-25T13:01:47Z

@guruz I tried the nightly build but no improvement. CPU Time with 1.8.0: 57.27 and with the nightly: 57.22.

But, I think I figured out where the usage comes from. First of all, from the above numbers one has to subtract about 20 seconds because during the first 40-50 seconds after starting ownCloud the program puts everything in place. So the net CPU time would be ~37 seconds.

As I stated before I believe that is has something to do with the Etag polling: So i did the following: I removed my 6 sync-folders and created 6 empty folders (named 1 to 6) and added them to ownCloud. I left the folder empty just make sure that it would not be the amount of Etag that cause the cpu usage (my Images-folder for example has several hundred of Etags). I started my measurement again and came up with this numbers: 43.11 in total minus 6.6 for the startup, means a net CPU Time of ~37 seconds.

I do believe that the server requests generate the cpu usage.

03-25 13:38:38:831 0x608000015a60 OCC::FolderMan::slotEtagPollTimerTimeout: void OCC::FolderMan::slotEtagPollTimerTimeout() The following folders need to check for the remote ETag: QSet("1", "2", "3", "4", "5", "6")
03-25 13:38:38:831 0x608000015a60 OCC::Folder::slotRunEtagJob: * Trying to check "1" for changes via ETag check. (time since last sync: 115 s)
03-25 13:38:38:831 0x608000015a60 OCC::Folder::slotRunEtagJob: * Trying to check "2" for changes via ETag check. (time since last sync: 112 s)
03-25 13:38:38:831 0x608000015a60 OCC::Folder::slotRunEtagJob: * Trying to check "3" for changes via ETag check. (time since last sync: 109 s)
03-25 13:38:38:831 0x608000015a60 OCC::Folder::slotRunEtagJob: * Trying to check "4" for changes via ETag check. (time since last sync: 106 s)
03-25 13:38:38:831 0x608000015a60 OCC::Folder::slotRunEtagJob: * Trying to check "5" for changes via ETag check. (time since last sync: 103 s)
03-25 13:38:38:832 0x608000015a60 OCC::Folder::slotRunEtagJob: * Trying to check "6" for changes via ETag check. (time since last sync: 100 s)
03-25 13:38:38:832 0x608000015a60 OCC::FolderMan::slotRunOneEtagJob: Scheduling "1" to check remote ETag
03-25 13:38:38:832 0x608000015a60 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for  QUrl( "https://kumori.fosuta.org" )  querying "1"
03-25 13:38:38:978 0x608000015a60 OCC::Folder::etagRetreived: * Compare etag with previous etag: last: ""5512ab1de03e0"" , received: ""5512ab1de03e0""
03-25 13:38:39:307 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858243f5d0)  with name  "1"
03-25 13:38:39:307 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858255ad60)  with name  "2"
03-25 13:38:39:307 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582564900)  with name  "3"
03-25 13:38:39:307 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582446c80)  with name  "4"
03-25 13:38:39:307 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858241ab60)  with name  "5"
03-25 13:38:39:307 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582423010)  with name  "6"
03-25 13:38:39:309 0x608000015a60 OCC::FolderMan::slotRunOneEtagJob: Scheduling "2" to check remote ETag
03-25 13:38:39:309 0x608000015a60 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for  QUrl( "https://kumori.fosuta.org" )  querying "2"
03-25 13:38:39:405 0x608000015a60 OCC::Folder::etagRetreived: * Compare etag with previous etag: last: ""5512ab2dd6e1e"" , received: ""5512ab2dd6e1e""
03-25 13:38:39:723 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858243f5d0)  with name  "1"
03-25 13:38:39:723 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858255ad60)  with name  "2"
03-25 13:38:39:724 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582564900)  with name  "3"
03-25 13:38:39:724 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582446c80)  with name  "4"
03-25 13:38:39:724 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858241ab60)  with name  "5"
03-25 13:38:39:724 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582423010)  with name  "6"
03-25 13:38:39:726 0x608000015a60 OCC::FolderMan::slotRunOneEtagJob: Scheduling "3" to check remote ETag
03-25 13:38:39:726 0x608000015a60 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for  QUrl( "https://kumori.fosuta.org" )  querying "3"
03-25 13:38:39:811 0x608000015a60 OCC::Folder::etagRetreived: * Compare etag with previous etag: last: ""5512ab3d4f725"" , received: ""5512ab3d4f725""
03-25 13:38:40:190 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858243f5d0)  with name  "1"
03-25 13:38:40:190 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858255ad60)  with name  "2"
03-25 13:38:40:190 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582564900)  with name  "3"
03-25 13:38:40:190 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582446c80)  with name  "4"
03-25 13:38:40:190 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858241ab60)  with name  "5"
03-25 13:38:40:190 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582423010)  with name  "6"
03-25 13:38:40:192 0x608000015a60 OCC::FolderMan::slotRunOneEtagJob: Scheduling "4" to check remote ETag
03-25 13:38:40:193 0x608000015a60 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for  QUrl( "https://kumori.fosuta.org" )  querying "4"
03-25 13:38:40:283 0x608000015a60 OCC::Folder::etagRetreived: * Compare etag with previous etag: last: ""5512ab4b4f929"" , received: ""5512ab4b4f929""
03-25 13:38:40:620 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858243f5d0)  with name  "1"
03-25 13:38:40:620 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858255ad60)  with name  "2"
03-25 13:38:40:620 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582564900)  with name  "3"
03-25 13:38:40:620 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582446c80)  with name  "4"
03-25 13:38:40:620 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858241ab60)  with name  "5"
03-25 13:38:40:620 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582423010)  with name  "6"
03-25 13:38:40:623 0x608000015a60 OCC::FolderMan::slotRunOneEtagJob: Scheduling "5" to check remote ETag
03-25 13:38:40:623 0x608000015a60 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for  QUrl( "https://kumori.fosuta.org" )  querying "5"
03-25 13:38:40:722 0x608000015a60 OCC::Folder::etagRetreived: * Compare etag with previous etag: last: ""5512ab5a8a39d"" , received: ""5512ab5a8a39d""
03-25 13:38:41:113 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858243f5d0)  with name  "1"
03-25 13:38:41:113 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858255ad60)  with name  "2"
03-25 13:38:41:114 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582564900)  with name  "3"
03-25 13:38:41:114 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582446c80)  with name  "4"
03-25 13:38:41:114 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858241ab60)  with name  "5"
03-25 13:38:41:114 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582423010)  with name  "6"
03-25 13:38:41:124 0x608000015a60 OCC::FolderMan::slotRunOneEtagJob: Scheduling "6" to check remote ETag
03-25 13:38:41:124 0x608000015a60 OCC::AbstractNetworkJob::start: !!! OCC::RequestEtagJob created for  QUrl( "https://kumori.fosuta.org" )  querying "6"
03-25 13:38:41:302 0x608000015a60 OCC::Folder::etagRetreived: * Compare etag with previous etag: last: ""5512ab6a5bc58"" , received: ""5512ab6a5bc58""
03-25 13:38:41:641 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858243f5d0)  with name  "1"
03-25 13:38:41:642 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858255ad60)  with name  "2"
03-25 13:38:41:642 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582564900)  with name  "3"
03-25 13:38:41:642 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582446c80)  with name  "4"
03-25 13:38:41:642 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f858241ab60)  with name  "5"
03-25 13:38:41:642 0x608000015a60 OCC::ownCloudGui::slotComputeOverallSyncStatus: Folder in overallStatus Message:  OCC::Folder(0x7f8582423010)  with name  "6"
03-25 13:38:41:645 0x608000015a60 OCC::FolderMan::slotRunOneEtagJob: No more remote ETag check jobs to schedule.

stonerl · 2015-03-25T13:06:53Z

Just forgot to mention. Every run took exactly 10 minutes.

Saves ~200msec on my not-so-old MBP on OS X. For #3007 #2990

guruz · 2015-03-25T15:57:34Z

This one has the commit above ^^
http://download.owncloud.com/desktop/daily/ownCloud-1.8.0.2220-nightly20150325.pkg

stonerl · 2015-03-25T18:41:22Z

This solved the bug. While idling oc doesn't use any CPU at all.

guruz · 2015-03-26T06:09:21Z

Thanks for the Analysis!

stonerl · 2015-03-26T12:24:04Z

@guruz Your're welcome!

guruz added this to the 1.8.1 - Bugfix milestone Mar 23, 2015

guruz added the type:bug label Mar 23, 2015

guruz added a commit that referenced this issue Mar 25, 2015

SslButton: Make menu creation lazy

e0ae34f

Saves ~200msec on my not-so-old MBP on OS X. For #3007 #2990

stonerl closed this as completed Mar 25, 2015

ckamm mentioned this issue Mar 26, 2015

[OSX][1.8.0] High CPU Usage #3007

Closed

ckamm mentioned this issue Apr 8, 2015

[osx] Client drawing a lot of power due to constant Icon refreshs #2937

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[OSX] CPU usage #2990

[OSX] CPU usage #2990

stonerl commented Mar 20, 2015

danimo commented Mar 20, 2015

stonerl commented Mar 20, 2015

guruz commented Mar 23, 2015

stonerl commented Mar 23, 2015

stonerl commented Mar 23, 2015

stonerl commented Mar 23, 2015

stonerl commented Mar 23, 2015

guruz commented Mar 23, 2015

stonerl commented Mar 23, 2015

guruz commented Mar 23, 2015

stonerl commented Mar 23, 2015

guruz commented Mar 25, 2015

stonerl commented Mar 25, 2015

stonerl commented Mar 25, 2015

guruz commented Mar 25, 2015

stonerl commented Mar 25, 2015

guruz commented Mar 26, 2015

stonerl commented Mar 26, 2015

[OSX] CPU usage #2990

[OSX] CPU usage #2990

Comments

stonerl commented Mar 20, 2015

danimo commented Mar 20, 2015

stonerl commented Mar 20, 2015

guruz commented Mar 23, 2015

stonerl commented Mar 23, 2015

stonerl commented Mar 23, 2015

stonerl commented Mar 23, 2015

stonerl commented Mar 23, 2015

guruz commented Mar 23, 2015

stonerl commented Mar 23, 2015

guruz commented Mar 23, 2015

stonerl commented Mar 23, 2015

guruz commented Mar 25, 2015

stonerl commented Mar 25, 2015

stonerl commented Mar 25, 2015

guruz commented Mar 25, 2015

stonerl commented Mar 25, 2015

guruz commented Mar 26, 2015

stonerl commented Mar 26, 2015