High CPU usage for changing single file, after using REST-API

njam · October 21, 2018, 2:01pm

In a folder with ~150k files I notice high CPU usage when adding a single empty file, after having used the REST API just before.

This is a problem, because many Syncthing status panels/icons use the REST API.

Usually when I add a single empty file to my folder, the CPU usage stays at 0.0%. Here’s the log of such an event:

log for adding an empty file "test/jo12" -> CPU 0.0%

[EUX7P] DEBUG: sendreceive/njam-home@0xc0001f4b00 filesystem notification rescan
[EUX7P] DEBUG: Walk [test/jo12] Matcher/[/.* /.*/** /VirtualBox VMs /VirtualBox VMs/**]@0xc000220090
[EUX7P] DEBUG: to hash: test/jo12 File{Name:"test/jo12", Sequence:0, Permissions:0644, ModTime:2018-10-21 14:56:42.613226998 +0200 CEST, Version:{[{EUX7PUQ 1}]}, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[]}
[EUX7P] DEBUG: real to hash: test/jo12
[EUX7P] DEBUG: Walk progress done njam-home [test/jo12] Matcher/[/.* /.*/** /VirtualBox VMs /VirtualBox VMs/**]@0xc000220090
[EUX7P] DEBUG: njam-home Update(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4, [1])
[EUX7P] DEBUG: insert; folder="njam-home" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 File{Name:"test/jo12", Sequence:6077934, Permissions:0644, ModTime:2018-10-21 14:56:42.613226998 +0200 CEST, Version:{[{EUX7PUQ 1}]}, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[Block{0/0/0/e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}]}
[EUX7P] DEBUG: update global; folder="njam-home" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="test/jo12" version={[{EUX7PUQ 1}]} invalid=false
[EUX7P] DEBUG: new global for "test/jo12" after update: {{{[{EUX7PUQ 1}]}, 7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4}}
[EUX7P] DEBUG: adding sequence; folder="njam-home" sequence=6077934 test/jo12
[EUX7P] DEBUG: njam-home WithPrefixedHaveTruncated(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4, "test/jo12")
[EUX7P] DEBUG: njam-home WithHaveSequence(6077934)
[EUX7P] DEBUG: njam-home WithHaveSequence(6077934)
[EUX7P] DEBUG: Sending indexes for njam-home to OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5 at [2a02:168:978a::f8d]:41816-[2a05:d014:d1b:5000:fe7c:8d39:f02c:3a13]:22000/tcp-client: 1 files (<98 bytes)
[EUX7P] DEBUG: njam-home WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
[EUX7P] DEBUG: Sending indexes for njam-home to 5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4 at [2a02:168:978a::f8d]:46322-[2a02:168:978a::214]:22000/tcp-client: 1 files (<98 bytes)
[EUX7P] DEBUG: Index update (in): OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5 / "njam-home": 1 files
[EUX7P] DEBUG: njam-home Update(OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5, [1])
[EUX7P] DEBUG: insert; folder="njam-home" device=OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5 File{Name:"test/jo12", Sequence:6114572, Permissions:0644, ModTime:2018-10-21 14:56:42.613226998 +0200 CEST, Version:{[{EUX7PUQ 1}]}, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[Block{0/0/0/e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}]}
[EUX7P] DEBUG: update global; folder="njam-home" device=OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5 file="test/jo12" version={[{EUX7PUQ 1}]} invalid=false
[EUX7P] DEBUG: new global for "test/jo12" after update: {{{[{EUX7PUQ 1}]}, OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5}, {{[{EUX7PUQ 1}]}, 7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4}}
[EUX7P] DEBUG: njam-home WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
[EUX7P] DEBUG: Index update (in): 5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4 / "njam-home": 1 files
[EUX7P] DEBUG: njam-home Update(5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4, [1])
[EUX7P] DEBUG: insert; folder="njam-home" device=5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4 File{Name:"test/jo12", Sequence:1185943, Permissions:0644, ModTime:2018-10-21 14:56:42.613226998 +0200 CEST, Version:{[{EUX7PUQ 1}]}, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[Block{0/0/0/e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}]}
[EUX7P] DEBUG: update global; folder="njam-home" device=5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4 file="test/jo12" version={[{EUX7PUQ 1}]} invalid=false
[EUX7P] DEBUG: new global for "test/jo12" after update: {{{[{EUX7PUQ 1}]}, 5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4}, {{[{EUX7PUQ 1}]}, OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5}, {{[{EUX7PUQ 1}]}, 7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4}}
[EUX7P] DEBUG: njam-home WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)

Now let’s say I open the Syncthing web interface to look at the status. If I add another single empty file now, the CPU usages increases to 100% just after adding the file. Here’s the log:

log for adding an empty file "test/jo13" -> CPU 100.0%

[EUX7P] DEBUG: sendreceive/njam-home@0xc0001f4b00 filesystem notification rescan
[EUX7P] DEBUG: Walk [test/jo13] Matcher/[/.* /.*/** /VirtualBox VMs /VirtualBox VMs/**]@0xc000220090
[EUX7P] DEBUG: to hash: test/jo13 File{Name:"test/jo13", Sequence:0, Permissions:0644, ModTime:2018-10-21 14:57:53.202172275 +0200 CEST, Version:{[{EUX7PUQ 1}]}, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[]}
[EUX7P] DEBUG: real to hash: test/jo13
[EUX7P] DEBUG: Walk progress done njam-home [test/jo13] Matcher/[/.* /.*/** /VirtualBox VMs /VirtualBox VMs/**]@0xc000220090
[EUX7P] DEBUG: njam-home Update(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4, [1])
[EUX7P] DEBUG: insert; folder="njam-home" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 File{Name:"test/jo13", Sequence:6077935, Permissions:0644, ModTime:2018-10-21 14:57:53.202172275 +0200 CEST, Version:{[{EUX7PUQ 1}]}, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[Block{0/0/0/e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}]}
[EUX7P] DEBUG: update global; folder="njam-home" device=7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4 file="test/jo13" version={[{EUX7PUQ 1}]} invalid=false
[EUX7P] DEBUG: new global for "test/jo13" after update: {{{[{EUX7PUQ 1}]}, 7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4}}
[EUX7P] DEBUG: adding sequence; folder="njam-home" sequence=6077935 test/jo13
[EUX7P] DEBUG: njam-home WithPrefixedHaveTruncated(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4, "test/jo13")
[EUX7P] DEBUG: njam-home WithHaveSequence(6077935)
[EUX7P] DEBUG: njam-home WithHaveSequence(6077935)
[EUX7P] DEBUG: Sending indexes for njam-home to 5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4 at [2a02:168:978a::f8d]:46322-[2a02:168:978a::214]:22000/tcp-client: 1 files (<97 bytes)
[EUX7P] DEBUG: njam-home WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
[EUX7P] DEBUG: Sending indexes for njam-home to OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5 at [2a02:168:978a::f8d]:41816-[2a05:d014:d1b:5000:fe7c:8d39:f02c:3a13]:22000/tcp-client: 1 files (<97 bytes)
[EUX7P] DEBUG: Index update (in): OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5 / "njam-home": 1 files
[EUX7P] DEBUG: njam-home Update(OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5, [1])
[EUX7P] DEBUG: insert; folder="njam-home" device=OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5 File{Name:"test/jo13", Sequence:6114573, Permissions:0644, ModTime:2018-10-21 14:57:53.202172275 +0200 CEST, Version:{[{EUX7PUQ 1}]}, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[Block{0/0/0/e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}]}
[EUX7P] DEBUG: update global; folder="njam-home" device=OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5 file="test/jo13" version={[{EUX7PUQ 1}]} invalid=false
[EUX7P] DEBUG: new global for "test/jo13" after update: {{{[{EUX7PUQ 1}]}, OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5}, {{[{EUX7PUQ 1}]}, 7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4}}
[EUX7P] DEBUG: njam-home WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
[EUX7P] DEBUG: Index update (in): 5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4 / "njam-home": 1 files
[EUX7P] DEBUG: njam-home Update(5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4, [1])
[EUX7P] DEBUG: insert; folder="njam-home" device=5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4 File{Name:"test/jo13", Sequence:1185944, Permissions:0644, ModTime:2018-10-21 14:57:53.202172275 +0200 CEST, Version:{[{EUX7PUQ 1}]}, Length:0, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[Block{0/0/0/e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855}]}
[EUX7P] DEBUG: update global; folder="njam-home" device=5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4 file="test/jo13" version={[{EUX7PUQ 1}]} invalid=false
[EUX7P] DEBUG: new global for "test/jo13" after update: {{{[{EUX7PUQ 1}]}, 5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4}, {{[{EUX7PUQ 1}]}, OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5}, {{[{EUX7PUQ 1}]}, 7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4}}
[EUX7P] DEBUG: njam-home WithNeed(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
[EUX7P] DEBUG: njam-home WithNeedTruncated(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
[EUX7P] DEBUG: progress emitter: bytes completed for njam-home: 0
[EUX7P] DEBUG: model@0xc0001ea7e0 NeedSize("njam-home"): {0 0 0 0 0 0 [] 0}
[EUX7P] DEBUG: njam-home WithNeedTruncated(OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5)
[EUX7P] DEBUG: model@0xc0001ea7e0 Completion(OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5, "njam-home"): 100.000000 (0 / 142519357509 = 0.000000)
[EUX7P] DEBUG: njam-home WithNeedTruncated(5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4)
[EUX7P] DEBUG: model@0xc0001ea7e0 Completion(5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4, "njam-home"): 100.000000 (0 / 142519357509 = 0.000000)

This behaviour of high CPU usage when changing single files persists for half a minute or so after the last API request was made, even after the browser window was closed.

The difference between the two logs is that the latter one has these additional lines at the end:

[EUX7P] DEBUG: njam-home WithNeedTruncated(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
[EUX7P] DEBUG: progress emitter: bytes completed for njam-home: 0
[EUX7P] DEBUG: model@0xc0001ea7e0 NeedSize("njam-home"): {0 0 0 0 0 0 [] 0}
[EUX7P] DEBUG: njam-home WithNeedTruncated(OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5)
[EUX7P] DEBUG: model@0xc0001ea7e0 Completion(OL5YS2A-XTFA54E-FUEMEQQ-OSVW5TE-ESDZH4W-OW5ENTN-Q4AQKSJ-IT6S7Q5, "njam-home"): 100.000000 (0 / 142519357509 = 0.000000)
[EUX7P] DEBUG: njam-home WithNeedTruncated(5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4)
[EUX7P] DEBUG: model@0xc0001ea7e0 Completion(5YT4NI6-24V6YNT-BY7XUDN-ZGQPH4G-W2YJQIQ-FMJ4PHS-XXSCHAW-GXAIIQ4, "njam-home"): 100.000000 (0 / 142519357509 = 0.000000)

I’m experiencing this behaviour also when running one of the two available GNOME extensions for Syncthing (1, 2). Since these extensions run all the time, the CPU usage for changing single files is high all the time.

Can someone explain to me which API requests result in this behaviour, and why? And is this expected behaviour? If this is expected behaviour, then any status panel/icon should probably use different APIs?

AudriusButkevicius · October 21, 2018, 2:56pm

Because calculating completion requires, what is missing etc, requires walking the whole database, potentially twice.

If the ui is not open, this information is not necessary, hence it’s not calculated.

I haven’t checked the logs but I am pretty positive that is the case.

njam · October 21, 2018, 4:16pm

Thanks for the explanation, that makes sense!

I did some more experiments. It seems when I send requests to /rest/events then subsequent file changes result in much higher CPU usage. When I stop sending requests to /rest/events for a minute or so, file changes don’t use CPU anymore.

So I assume when using the Events API some additional information is eagerly calculated (e.g. “completion”), so it can be included in the generated events? It’s noteworthy that the CPU usage even increases if I subscribe to specific event types which are completely unrelated to “completion”, like ConfigSaved.

It’s a pity because that makes the Events API not a good fit for “status icon” applications.

But I can see that using the endpoints /rest/db/status (for folder status) and /rest/system/connections (for network status) don’t incur any additional CPU usage.

This is in contradiction to the warnings in the documentation. Docs for /rest/db/status have a note “This is an expensive call”, but docs for /rest/events don’t. Should I open a ticket about it?

AudriusButkevicius · October 21, 2018, 5:49pm

Perhaps the code that checks if completion recalcation needs to be done is not event subscription type aware. Anyways, syncthing uses cpu, sure, I don’t think opening a ticket is going to make it not use cpu.

njam · October 21, 2018, 7:19pm

I meant to open a ticket for adding a warning on the docs for /rest/events that this is also an “expensive call”.

Either way, thanks a lot for your quick answers!

imsodin · October 21, 2018, 9:11pm

Events are sent regardless of subscriptions, ~~i.e. a subscription has no influence on e.g. when folder summaries are triggered.~~ That’s just plain wrong. Other than folder summaries, I don’t think any status calculation is done except on demand (from rest). ~~So I’d say what you see with running UI is sensible, but the events observation is probably bogous (something else going on at the same time?).~~

njam · October 22, 2018, 6:21am

In my second experiment I didn’t run the web interface, but only used curl to send requests to the Events API. That alone lead to observing high CPU spikes when changing a single file.

Is it something I should investigate further, or you it’s considered normal?

btw I’m running syncthing 0.14.51.

imsodin · October 22, 2018, 7:40am

That’s it. And fixing it is simple, so I don’t really get the point of your second sentence: Sure it will still use cpu, but less.

@njam If you file an enhancement ticket on the main repo about cpu usage when requesting events other than FolderSummary, I’ll propose a fix.

AudriusButkevicius · October 22, 2018, 8:04am

My point is that this is going into micro-optimization territory. At worst it’s cpu usage every 2s and I suspect you can’t even notice it if you run on a modern machine.

njam · October 22, 2018, 8:31am

Maybe I’m doing my benchmarks wrong (I hope so :>). But I’ve reproduced this on two different PCs.

Both use < 1% CPU when changing a single file in a folder with a total of 150k files. When I use the Events API at that same time, then such a change results in ~120% CPU usage on the machine with a “i7-7500U” CPU, and ~40% CPU usage on the machine with a “i7 8700K” CPU.

Is it easy for me to just disable the FolderSummary event alltogether in the code? If you can point me to the file where I would do that, then I can recompile and see if that helps.

imsodin · October 22, 2018, 9:14am

You can try this: ~~https://github.com/imsodin/syncthing/commit/db642e61581b1fe61bfe226959a686eaea19a05e~~ https://github.com/imsodin/syncthing/commit/5821da64b526ead52ed50185fe2c6dbf46c5c122

However folder summary events are probably essential to any wrapper, so I think it comes down to what Audrius said: I will anyway just use cpu. And I don’t see why a folder summary should use notable resources (just 100% cpu doesn’t mean much, if it’s just a sudden spike).

AudriusButkevicius · October 22, 2018, 11:56am

Added a comment on that.

njam · October 23, 2018, 7:58pm

As you guys guessed the reason seems to be folder summary events. Here’s a flamegraph of a 30 seconds profiling session with a single file change event:

I couldn’t test your commit yet, but I will do it soon.

njam · October 27, 2018, 3:56pm

@imsodin I have tested your commit, and it indeed solves the problem. But I agree with you, that probably most clients will use FolderSummary anyways.

I think we can leave it that. For clients that are only interested in the overall system status, using /rest/db/status (for folder status) and /rest/system/connections (for network status) is a good workaround.

Thank you very much for the help and the quick answers!

njam · October 27, 2018, 5:43pm

It’s maybe noteworthy that what really uses the CPU cycles is the calculation of FolderCompletion within sendSummary() - so the calculation of the remote status, not of the local status. Its calculation seems to iterater over all files in withNeed(). This can also be seen in the above flamegraph.

system · November 26, 2018, 5:48pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

High CPU usage for changing single file, *after* using REST-API

High CPU usage for changing single file, after using REST-API