Bug 270272

Summary: ktorrent uses a lot of cpu when idle
Product: [Applications] ktorrent Reporter: Con Kolivas <kde>
Component: generalAssignee: Joris Guisson <joris.guisson>
Status: RESOLVED FIXED    
Severity: normal    
Priority: NOR    
Version: unspecified   
Target Milestone: ---   
Platform: Ubuntu   
OS: Linux   
Latest Commit: Version Fixed In:
Sentry Crash Report:
Attachments: oprofile of ktorrent running

Description Con Kolivas 2011-04-07 05:08:57 UTC 
Version:           unspecified (using KDE 4.6.0) 
OS:                Linux

I usually have ktorrent running at all times. However there are times when I have removed all torrents from it and it has no torrents loaded. Despite that, it uses almost 10% (of one) CPU on a 3Ghz quad core machine. That much unnecessary polling of $something when there's nothing to do is excessive.

Reproducible: Always

Steps to Reproduce:
Remove all torrents and observe CPU usage.

Actual Results:  
CPU usage remains at 10%

Expected Results:  
CPU usage should be below measurable levels.
Comment 1 Joris Guisson 2011-04-10 11:09:02 UTC 
Is DHT enabled ?
Is µTP enabled ?

What do you see in the logging when this happens ?
Comment 2 Con Kolivas 2011-04-10 14:23:02 UTC 
DHT and µTP is enabled. If I start ktorrent without any torrents loaded it's quiet CPU-wise. If I load a torrent and let it finish, then close and remove the torrent, the CPU usage remains ~10%. I'm not sure what logging in particular you speak of. Confirmed to still be present in kde 4.6.2 as well.
Comment 3 Joris Guisson 2011-04-11 18:57:56 UTC 
There is a logviewer plugin to view the logging.
Comment 4 Joris Guisson 2011-04-11 18:59:03 UTC 
Btw, what version are you using ?
Comment 5 Con Kolivas 2011-04-12 06:45:10 UTC 
I'm using version 4.0.3.

While investigating what would show up in the logs, I enabled the logviewer. Then I tried repeating the steps outlined above to create the problem. Once the torrent was finished, I closed the integrity check dialog, and then removed the last torrent. After that lots of "invalid token" errors appeared in the logviewer, and then ktorrent crashed before I could copy the error, with this crash:
https://bugs.kde.org/show_bug.cgi?id=270733

Other things that might be relevant: The filenames are in Japanese, the integrity checker is enabled, and I'm running my own kernel (not surprisingly). As my kernel has subtick accounting, it is possible that the CPU usage may not show up in a mainline accounting, falling below the radar if every wakeup and sleep of ktorrent happens in under one scheduler tick.
Comment 6 Con Kolivas 2011-04-13 09:45:44 UTC 
I tried again and after removing the torrent it didn't crash this time, but I still get this in the logs:

Wed Apr 13 17:50:18 2011: Pinging questionable node : [::ffff:219.75.38.243]:41054
Wed Apr 13 17:50:19 2011: Pinging questionable node : [::ffff:85.247.114.253]:24036
Wed Apr 13 17:50:20 2011: DHT: got findNode request
Wed Apr 13 17:50:25 2011: DHT: got findNode request
Wed Apr 13 17:50:25 2011: DHT: Sending ping response
Wed Apr 13 17:50:27 2011: DHT: got findNode request
Wed Apr 13 17:50:30 2011: DHT: got findNode request
Wed Apr 13 17:50:31 2011: DHT: got findNode request
Wed Apr 13 17:50:31 2011: DHT: got findNode request
Wed Apr 13 17:50:31 2011: Pinging questionable node : [::ffff:2.102.116.177]:34602
Wed Apr 13 17:50:32 2011: DHT: got findNode request
Wed Apr 13 17:50:32 2011: Pinging questionable node : [::ffff:2.102.116.177]:34602
Wed Apr 13 17:50:32 2011: Pinging questionable node : [::ffff:58.69.145.90]:32806
Wed Apr 13 17:50:33 2011: Pinging questionable node : [::ffff:58.69.145.90]:32806
Wed Apr 13 17:50:34 2011: Pinging questionable node : [::ffff:2.60.4.181]:29211
Wed Apr 13 17:50:35 2011: DHT: got findNode request
Wed Apr 13 17:50:35 2011: Accepted connection from [::ffff:174.115.150.61]:50396
Wed Apr 13 17:50:36 2011: DHT: got findNode request
Wed Apr 13 17:50:39 2011: Error thrown: Illegal token: 65
Wed Apr 13 17:50:39 2011: Error happened during parsing : Illegal token: 65
Wed Apr 13 17:50:40 2011: DHT: got findNode request
Wed Apr 13 17:50:40 2011: DHT: got findNode request
Wed Apr 13 17:50:40 2011: Pinging questionable node : [::ffff:188.143.56.136]:8080
Wed Apr 13 17:50:41 2011: DHT: got findNode request
Wed Apr 13 17:50:41 2011: DHT: got findNode request
Wed Apr 13 17:50:41 2011: Pinging questionable node : [::ffff:93.13.138.204]:6800
Wed Apr 13 17:50:42 2011: Pinging questionable node : [::ffff:71.211.46.96]:44904
Wed Apr 13 17:50:42 2011: DHT: got getPeers request
Wed Apr 13 17:50:42 2011: Error thrown: Illegal token: 65
Wed Apr 13 17:50:42 2011: Error happened during parsing : Illegal token: 65
Wed Apr 13 17:50:42 2011: Error thrown: Illegal token: 65
Wed Apr 13 17:50:42 2011: Error happened during parsing : Illegal token: 65
Wed Apr 13 17:50:43 2011: Accepted connection from [::ffff:213.47.114.7]:52132
Wed Apr 13 17:50:43 2011: Pinging questionable node : [::ffff:75.71.131.11]:1024
Wed Apr 13 17:50:44 2011: Pinging questionable node : [::ffff:217.195.50.165]:48067
Wed Apr 13 17:50:44 2011: Accepted connection from [::ffff:213.47.114.7]:52133
Wed Apr 13 17:50:44 2011: Accepted connection from [::ffff:96.224.49.187]:49420
Wed Apr 13 17:50:45 2011: DHT: got findNode request
Wed Apr 13 17:50:45 2011: Pinging questionable node : [::ffff:98.229.30.136]:25992
Wed Apr 13 17:50:45 2011: Error thrown: Illegal token: 65
Wed Apr 13 17:50:45 2011: Error happened during parsing : Illegal token: 65
Wed Apr 13 17:50:46 2011: DHT: got findNode request
Wed Apr 13 17:50:46 2011: Pinging questionable node : [::ffff:70.145.133.40]:50700
Wed Apr 13 17:50:47 2011: DHT: got findNode request
Wed Apr 13 17:50:47 2011: Pinging questionable node : [::ffff:81.243.164.72]:10584
Wed Apr 13 17:50:47 2011: Pinging questionable node : [::ffff:74.14.209.220]:25146
Wed Apr 13 17:50:48 2011: Pinging questionable node : [::ffff:85.24.200.76]:6881
Wed Apr 13 17:50:49 2011: Pinging questionable node : [::ffff:128.59.235.111]:38945
Wed Apr 13 17:50:49 2011: Pinging questionable node : [::ffff:85.224.244.82]:63836
Wed Apr 13 17:50:50 2011: Pinging questionable node : [::ffff:112.138.42.69]:23115
Wed Apr 13 17:50:50 2011: Pinging questionable node : [::ffff:175.193.89.177]:16463
Wed Apr 13 17:50:51 2011: DHT: got findNode request
Wed Apr 13 17:50:51 2011: Pinging questionable node : [::ffff:188.241.114.70]:6918
Wed Apr 13 17:50:51 2011: Pinging questionable node : [::ffff:76.169.12.152]:49001
Wed Apr 13 17:50:51 2011: Pinging questionable node : [::ffff:213.186.252.188]:63024
Wed Apr 13 17:50:51 2011: Accepted connection from [::ffff:211.8.5.218]:4937
Wed Apr 13 17:50:52 2011: Pinging questionable node : [::ffff:85.221.179.101]:6881
Wed Apr 13 17:50:52 2011: Pinging questionable node : [::ffff:87.8.102.38]:49740
Wed Apr 13 17:50:52 2011: Pinging questionable node : [::ffff:93.189.74.30]:47802
Wed Apr 13 17:50:53 2011: DHT: got findNode request
Wed Apr 13 17:50:53 2011: Pinging questionable node : [::ffff:85.221.179.101]:6881
Wed Apr 13 17:50:53 2011: Pinging questionable node : [::ffff:77.121.87.141]:49143
Wed Apr 13 17:50:54 2011: Pinging questionable node : [::ffff:123.193.22.199]:11623
Wed Apr 13 17:50:54 2011: Pinging questionable node : [::ffff:93.13.29.167]:4151
Wed Apr 13 17:50:54 2011: DHT: got findNode request
Wed Apr 13 17:50:54 2011: Pinging questionable node : [::ffff:123.193.22.199]:11623
Wed Apr 13 17:50:55 2011: Pinging questionable node : [::ffff:222.108.233.41]:13686
Wed Apr 13 17:50:56 2011: DHT: got findNode request
Wed Apr 13 17:50:56 2011: Pinging questionable node : [::ffff:97.106.182.223]:35331
Wed Apr 13 17:50:56 2011: DHT: got findNode request
Wed Apr 13 17:50:57 2011: Pinging questionable node : [::ffff:85.245.179.178]:49880
Wed Apr 13 17:51:02 2011: Accepted connection from [::ffff:112.198.64.165]:42040
Wed Apr 13 17:51:02 2011: Pinging questionable node : [::ffff:207.216.69.195]:51977
Wed Apr 13 17:51:03 2011: Pinging questionable node : [::ffff:110.33.186.66]:54435
Wed Apr 13 17:51:04 2011: DHT: got findNode request
Wed Apr 13 17:51:04 2011: Pinging questionable node : [::ffff:94.99.80.217]:27967
Wed Apr 13 17:51:06 2011: Accepted connection from [::ffff:174.115.150.61]:50469
Wed Apr 13 17:51:06 2011: DHT: got findNode request
Wed Apr 13 17:51:06 2011: Pinging questionable node : [::ffff:85.245.179.178]:49880
Wed Apr 13 17:51:07 2011: DHT: got findNode request
Wed Apr 13 17:51:08 2011: DHT: got findNode request
Wed Apr 13 17:51:08 2011: Pinging questionable node : [::ffff:58.6.47.55]:32323
Wed Apr 13 17:51:09 2011: Pinging questionable node : [::ffff:95.160.138.36]:15354
Wed Apr 13 17:51:09 2011: Accepted connection from [::ffff:70.129.186.15]:35351
Wed Apr 13 17:51:10 2011: Accepted connection from [::ffff:70.129.186.15]:34869
Wed Apr 13 17:51:10 2011: Pinging questionable node : [::ffff:151.68.153.141]:48937
Wed Apr 13 17:51:12 2011: DHT: got findNode request
Wed Apr 13 17:51:12 2011: Pinging questionable node : [::ffff:89.253.95.35]:6881
Wed Apr 13 17:51:13 2011: Pinging questionable node : [::ffff:46.162.79.170]:49674
Wed Apr 13 17:51:14 2011: Accepted connection from [::ffff:114.176.114.24]:17721
Wed Apr 13 17:51:16 2011: DHT: got findNode request
Wed Apr 13 17:51:17 2011: Pinging questionable node : [::ffff:116.15.81.20]:51413
Wed Apr 13 17:51:18 2011: DHT: got findNode request
Wed Apr 13 17:51:18 2011: Pinging questionable node : [::ffff:90.58.219.134]:41792
Wed Apr 13 17:51:19 2011: Pinging questionable node : [::ffff:194.28.184.168]:14225
Wed Apr 13 17:51:19 2011: DHT: got findNode request
Wed Apr 13 17:51:20 2011: Pinging questionable node : [::ffff:194.28.184.168]:14225
Wed Apr 13 17:51:26 2011: DHT: got findNode request
Wed Apr 13 17:51:28 2011: DHT: got findNode request
Wed Apr 13 17:51:28 2011: DHT: got findNode request
Wed Apr 13 17:51:29 2011: Accepted connection from [::ffff:24.255.47.28]:57243
Wed Apr 13 17:51:34 2011: Pinging questionable node : [::ffff:84.252.29.64]:47442
Wed Apr 13 17:51:37 2011: DHT: got findNode request
Wed Apr 13 17:51:37 2011: Pinging questionable node : [::ffff:85.234.174.81]:22809
Wed Apr 13 17:51:37 2011: DHT: got findNode request
Wed Apr 13 17:51:37 2011: DHT: got findNode request
Wed Apr 13 17:51:38 2011: Pinging questionable node : [::ffff:99.112.31.169]:14307
Wed Apr 13 17:51:39 2011: Pinging questionable node : [::ffff:145.53.205.26]:53515
Wed Apr 13 17:51:39 2011: DHT: got findNode request
Wed Apr 13 17:51:40 2011: Pinging questionable node : [::ffff:173.238.209.99]:60886
Wed Apr 13 17:51:41 2011: Pinging questionable node : [::ffff:90.155.161.143]:33294
Wed Apr 13 17:51:41 2011: Accepted connection from [::ffff:58.8.245.68]:61887
Wed Apr 13 17:51:42 2011: Pinging questionable node : [::ffff:62.178.148.119]:6881
Wed Apr 13 17:51:42 2011: DHT: got getPeers request
Wed Apr 13 17:51:43 2011: Pinging questionable node : [::ffff:124.168.72.239]:6881
Wed Apr 13 17:51:43 2011: Pinging questionable node : [::ffff:203.147.62.148]:45492
Wed Apr 13 17:51:44 2011: Pinging questionable node : [::ffff:68.70.227.7]:6881
Wed Apr 13 17:51:44 2011: Pinging questionable node : [::ffff:203.147.62.148]:45492
Wed Apr 13 17:51:44 2011: DHT: got findNode request
Wed Apr 13 17:51:45 2011: Pinging questionable node : [::ffff:122.169.220.9]:27837
Wed Apr 13 17:51:45 2011: DHT: refreshing bucket 
Wed Apr 13 17:51:45 2011: Accepted connection from [::ffff:211.8.5.218]:1234
Wed Apr 13 17:51:46 2011: Pinging questionable node : [::ffff:175.140.109.254]:39886
Wed Apr 13 17:51:47 2011: Pinging questionable node : [::ffff:113.190.7.208]:14507

and it kept going on after that...
Comment 7 Joris Guisson 2011-04-13 18:50:59 UTC 
That's just handling incoming DHT packets. Which should not take much CPU at all.
If it is DHT, you can try disabling it when this happens. If the CPU usage drops, the problem must be there. 

How many nodes do you have in DHT ? 

> Other things that might be relevant: The filenames are in Japanese, the
> integrity checker is enabled, and I'm running my own kernel (not surprisingly).
> As my kernel has subtick accounting, it is possible that the CPU usage may not
> show up in a mainline accounting, falling below the radar if every wakeup and
> sleep of ktorrent happens in under one scheduler tick.

I'm running your patch set with a 2.6.37 kernel. I'm not seeing such behavior after a torrent is stopped and only DHT is running. KTorrent occasionally goes to 1-2 % of CPU usage in top, and this on a 2Ghz core 2 duo.
Comment 8 Con Kolivas 2011-04-14 11:49:11 UTC 
Turning DHT off didn't make a difference:

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P COMMAND                                                                          3929 con        1   0  610m  68m  32m S  9.2  0.9   0:21.83 0 ktorrent                                                                                                          
no torrents are currently loaded, and dht was turned off after one torrent finished

Restarting ktorrent drops its CPU usage to 2~5% Which is still kind of a lot for an idle application with no torrents loaded.
Comment 9 Joris Guisson 2011-04-16 11:26:06 UTC 
Would it be possible to run oprofile ?
Comment 10 Con Kolivas 2011-09-19 00:01:41 UTC 
Created attachment 63758 [details]
oprofile of ktorrent running

This is the profile of an otherwise mostly idle desktop when ktorrent is the largest CPU consumer by far. After a torrent has been downloaded and all torrents are unloaded, the CPU usage stays at 10%.
Comment 11 Joris Guisson 2011-09-20 16:24:11 UTC 
So lots of mutex locking and unlocking is causing the problem.

Then the problem must be in the µTP code.
Comment 12 Joris Guisson 2011-09-20 16:26:04 UTC 
Btw what is Network sleep interval set to in the advanced settings ?
Comment 13 Con Kolivas 2011-09-20 22:05:36 UTC 
Never changed it. It says 50ms.
Comment 14 Joris Guisson 2011-10-29 08:50:58 UTC 
Recent µTP performance improvements should also fix this.