Processing time of "Clean Database"
#1
Since the release of KODI I have the impression that the "Clean Database" command takes far longer time.
The last operation took me approximately half an hour. While the database was cleaned I had a look at the CPU und MEM usage of my raspberry pi.
The CPU usage was below 10%. Why does the KODI not use the full potential of the processor in this case?

Any ideas?

Regards, sega.
Reply
#2
Can you enable debugging an check if anything is in kodi.log when this happens?
Reply
#3
This is the log with debuggin enabled. Took 32 minutes this time with a CPU usage close to idle.
My database consists of ~ 150 movies and ~ 50 series.

Code:
20:00:31 T:3038511104  NOTICE: CleanDatabase: Starting videodatabase cleanup ..
20:00:31 T:3038511104   DEBUG: CAnnouncementManager - Announcement: OnCleanStarted from xbmc
20:00:31 T:3038511104   DEBUG: GOT ANNOUNCEMENT, type: 16, from xbmc, message OnCleanStarted
20:00:31 T:3038511104   DEBUG: DialogProgress::StartModal called
20:00:31 T:3038511104   DEBUG: ------ Window Init (DialogProgress.xml) ------
20:00:32 T:2770334784   DEBUG: webserver: request received for /jsonrpc
20:02:37 T:3038511104   DEBUG: Previous line repeats 30 times.
20:02:37 T:3038511104   DEBUG: CAnnouncementManager - Announcement: OnScreensaverActivated from xbmc
20:02:37 T:3038511104   DEBUG: GOT ANNOUNCEMENT, type: 4, from xbmc, message OnScreensaverActivated
20:02:37 T:3038511104   DEBUG: ------ Window Init () ------
20:05:05 T:2795500608   DEBUG: webserver: request received for /jsonrpc
20:27:51 T:3038511104   DEBUG: Previous line repeats 36 times.
20:31:40 T:3038511104   DEBUG: SECTION:LoadDLL(libnfs.so.1)
20:31:40 T:3038511104   DEBUG: Loading: /opt/xbmc-bcm/xbmc-bin/lib/kodi/system/libnfs.so.1
20:31:40 T:3038511104   DEBUG: NFS: Context for IP/volume1/Serien not open - get a new context.
20:31:40 T:3038511104   DEBUG: NFS: Connected to server IP and export /volume1/Serien
20:31:40 T:3038511104   DEBUG: NFS: chunks: r/w 131072/32768
20:32:27 T:3038511104   DEBUG: NFS: Context for IP/volume1/HD-Videos not open - get a new context.
20:32:27 T:3038511104   DEBUG: NFS: Connected to server IP and export /volume1/HD-Videos
20:32:27 T:3038511104   DEBUG: NFS: chunks: r/w 131072/32768
20:32:27 T:3038511104   DEBUG: NFS: Context for IP/volume1/SD-Videos not open - get a new context.
20:32:27 T:3038511104   DEBUG: NFS: Connected to server IP and export /volume1/SD-Videos
20:32:27 T:3038511104   DEBUG: NFS: chunks: r/w 131072/32768
20:32:29 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/Serien, old: 88534153, new: 88582566
20:32:29 T:3038511104   DEBUG: NFS: Using cached context.
20:32:29 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/HD-Videos, old: 88581117, new: 88582848
20:32:29 T:3038511104   DEBUG: NFS: Using cached context.
20:32:29 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/SD-Videos, old: 88581255, new: 88583039
20:32:29 T:3038511104   DEBUG: NFS: Using cached context.
20:32:30 T:3038511104   DEBUG: CleanDatabase: Cleaning paths that don't exist and have content set...
20:32:30 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/Serien, old: 88582566, new: 88584249
20:32:30 T:3038511104   DEBUG: NFS: Using cached context.
20:32:33 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/HD-Videos, old: 88582848, new: 88586882
20:32:33 T:3038511104   DEBUG: NFS: Using cached context.
20:32:33 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/SD-Videos, old: 88583039, new: 88586939
20:32:33 T:3038511104   DEBUG: NFS: Using cached context.
20:32:34 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/HD-Videos, old: 88586882, new: 88587736
20:32:34 T:3038511104   DEBUG: NFS: Using cached context.
20:32:34 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/SD-Videos, old: 88586939, new: 88587854
20:32:34 T:3038511104   DEBUG: NFS: Using cached context.
20:32:34 T:3038511104   DEBUG: CleanDatabase: Cleaning tvshow table
20:32:34 T:3038511104   DEBUG: CleanDatabase: Cleaning path table
20:32:35 T:3038511104   DEBUG: CleanDatabase: Cleaning genre table
20:32:35 T:3038511104   DEBUG: CleanDatabase: Cleaning country table
20:32:35 T:3038511104   DEBUG: CleanDatabase: Cleaning actor table of actors, directors and writers
20:32:35 T:3038511104   DEBUG: CleanDatabase: Cleaning studio table
20:32:36 T:3038511104   DEBUG: CleanDatabase: Cleaning set table
20:32:36 T:3038511104  NOTICE: CleanDatabase: Cleaning videodatabase done. Operation took 32:05
20:32:36 T:3038511104   DEBUG: CAnnouncementManager - Announcement: OnCleanFinished from xbmc
20:32:36 T:3038511104   DEBUG: GOT ANNOUNCEMENT, type: 16, from xbmc, message OnCleanFinished
20:32:36 T:3038511104   DEBUG: ------ Window Deinit (DialogProgress.xml) ------
Reply
#4
(2015-01-16, 21:40)therealsega Wrote: This is the log with debuggin enabled. Took 32 minutes this time with a CPU usage close to idle.
My database consists of ~ 150 movies and ~ 50 series.

Code:
20:00:31 T:3038511104  NOTICE: CleanDatabase: Starting videodatabase cleanup ..
20:00:31 T:3038511104   DEBUG: CAnnouncementManager - Announcement: OnCleanStarted from xbmc
20:00:31 T:3038511104   DEBUG: GOT ANNOUNCEMENT, type: 16, from xbmc, message OnCleanStarted
20:00:31 T:3038511104   DEBUG: DialogProgress::StartModal called
20:00:31 T:3038511104   DEBUG: ------ Window Init (DialogProgress.xml) ------
20:00:32 T:2770334784   DEBUG: webserver: request received for /jsonrpc
20:02:37 T:3038511104   DEBUG: Previous line repeats 30 times.
20:02:37 T:3038511104   DEBUG: CAnnouncementManager - Announcement: OnScreensaverActivated from xbmc
20:02:37 T:3038511104   DEBUG: GOT ANNOUNCEMENT, type: 4, from xbmc, message OnScreensaverActivated
20:02:37 T:3038511104   DEBUG: ------ Window Init () ------
20:05:05 T:2795500608   DEBUG: webserver: request received for /jsonrpc
20:27:51 T:3038511104   DEBUG: Previous line repeats 36 times.
20:31:40 T:3038511104   DEBUG: SECTION:LoadDLL(libnfs.so.1)
20:31:40 T:3038511104   DEBUG: Loading: /opt/xbmc-bcm/xbmc-bin/lib/kodi/system/libnfs.so.1
20:31:40 T:3038511104   DEBUG: NFS: Context for IP/volume1/Serien not open - get a new context.
20:31:40 T:3038511104   DEBUG: NFS: Connected to server IP and export /volume1/Serien
20:31:40 T:3038511104   DEBUG: NFS: chunks: r/w 131072/32768
20:32:27 T:3038511104   DEBUG: NFS: Context for IP/volume1/HD-Videos not open - get a new context.
20:32:27 T:3038511104   DEBUG: NFS: Connected to server IP and export /volume1/HD-Videos
20:32:27 T:3038511104   DEBUG: NFS: chunks: r/w 131072/32768
20:32:27 T:3038511104   DEBUG: NFS: Context for IP/volume1/SD-Videos not open - get a new context.
20:32:27 T:3038511104   DEBUG: NFS: Connected to server IP and export /volume1/SD-Videos
20:32:27 T:3038511104   DEBUG: NFS: chunks: r/w 131072/32768
20:32:29 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/Serien, old: 88534153, new: 88582566
20:32:29 T:3038511104   DEBUG: NFS: Using cached context.
20:32:29 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/HD-Videos, old: 88581117, new: 88582848
20:32:29 T:3038511104   DEBUG: NFS: Using cached context.
20:32:29 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/SD-Videos, old: 88581255, new: 88583039
20:32:29 T:3038511104   DEBUG: NFS: Using cached context.
20:32:30 T:3038511104   DEBUG: CleanDatabase: Cleaning paths that don't exist and have content set...
20:32:30 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/Serien, old: 88582566, new: 88584249
20:32:30 T:3038511104   DEBUG: NFS: Using cached context.
20:32:33 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/HD-Videos, old: 88582848, new: 88586882
20:32:33 T:3038511104   DEBUG: NFS: Using cached context.
20:32:33 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/SD-Videos, old: 88583039, new: 88586939
20:32:33 T:3038511104   DEBUG: NFS: Using cached context.
20:32:34 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/HD-Videos, old: 88586882, new: 88587736
20:32:34 T:3038511104   DEBUG: NFS: Using cached context.
20:32:34 T:3038511104   DEBUG: NFS: Refreshing context for IP/volume1/SD-Videos, old: 88586939, new: 88587854
20:32:34 T:3038511104   DEBUG: NFS: Using cached context.
20:32:34 T:3038511104   DEBUG: CleanDatabase: Cleaning tvshow table
20:32:34 T:3038511104   DEBUG: CleanDatabase: Cleaning path table
20:32:35 T:3038511104   DEBUG: CleanDatabase: Cleaning genre table
20:32:35 T:3038511104   DEBUG: CleanDatabase: Cleaning country table
20:32:35 T:3038511104   DEBUG: CleanDatabase: Cleaning actor table of actors, directors and writers
20:32:35 T:3038511104   DEBUG: CleanDatabase: Cleaning studio table
20:32:36 T:3038511104   DEBUG: CleanDatabase: Cleaning set table
20:32:36 T:3038511104  NOTICE: CleanDatabase: Cleaning videodatabase done. Operation took 32:05
20:32:36 T:3038511104   DEBUG: CAnnouncementManager - Announcement: OnCleanFinished from xbmc
20:32:36 T:3038511104   DEBUG: GOT ANNOUNCEMENT, type: 16, from xbmc, message OnCleanFinished
20:32:36 T:3038511104   DEBUG: ------ Window Deinit (DialogProgress.xml) ------

How many videos in total? That sounds like a lot. Cleaning my database of 577 videos took quite some time. I am going to have to do it again today as the wife and I want it so the kids don't come across films that aren't really suitable. Tell us a little about your Pi.
HTPCs: 2 x Chromecast with Google TV
Audio: Pioneer VSX-819HK & S-HS 100 5.1 Speakers
Server: HP Compaq Pro 6300, 4GB RAM, 8.75TB, Bodhi Linux 5.x, NFS, MySQL
Reply
#5
(2015-01-16, 21:40)therealsega Wrote: This is the log with debuggin enabled. Took 32 minutes this time with a CPU usage close to idle.
My database consists of ~ 150 movies and ~ 50 series.
Code:
20:05:05 T:2795500608   DEBUG: webserver: request received for /jsonrpc
20:27:51 T:3038511104   DEBUG: Previous line repeats 36 times.

You should post complete log and use a paste site (e.g. pastebin).
Did you clean using a http (e.g. phone) remote app?
Is it any different when selecting "clean library" from settings/video/library?

I've just tried cleaning a big library (1500 movies, 30000 TV episodes) and it does take a while, although for me it's about 5 minutes.
CPU usage is not that high because most of the time is spent doing existence checks on file system:
Code:
#0  0xb61cca70 in poll () from /opt/bcm-rootfs/lib/arm-linux-gnueabihf/libc.so.6
#1  0xad03cd04 in wait_for_nfs_reply () from /opt/xbmc-bcm/xbmc-dbg/arm-linux-gnueabihf/arm-linux-gnueabihf/lib/libnfs.so.4.3.0
#2  0xad03cffc in nfs_stat () from /opt/xbmc-bcm/xbmc-dbg/arm-linux-gnueabihf/arm-linux-gnueabihf/lib/libnfs.so.4.3.0
#3  0x007a8fe8 in XFILE::CNFSFile::Stat (this=<optimised out>, url=..., buffer=0x0) at NFSFile.cpp:603
#4  0x007a5cb8 in XFILE::CNFSFile::Exists (this=<optimised out>, url=...) at NFSFile.cpp:582
#5  0x007102e0 in XFILE::CFile::Exists (file=..., bUseCache=bUseCache@entry=false) at File.cpp:379
#6  0x00710640 in XFILE::CFile::Exists (strFileName=..., bUseCache=<optimised out>) at File.cpp:357
#7  0x00484b28 in CVideoDatabase::CleanDatabase (this=this@entry=0x2fb3428, handle=0x20c6ee8, handle@entry=0x0, paths=paths@entry=0x0, showProgress=showProgress@entry=true) at VideoDatabase.cpp:7883
#8  0x004c3e88 in VIDEO::CVideoInfoScanner::CleanDatabase (this=0x2fb3240, handle=0x0, paths=0x0, showProgress=<optimised out>) at VideoInfoScanner.cpp:251
#9  0x0044cac0 in CMediaSettings::OnSettingAction (this=<optimised out>, setting=<optimised out>) at MediaSettings.cpp:336
#10 0x008d69cc in CSettingsManager::OnSettingAction (this=<optimised out>, setting=0x304f308) at SettingsManager.cpp:797
#11 0x008e19bc in CGUIControlButtonSetting::OnClick (this=0xa8617078) at GUIControlSettings.cpp:551
#12 0x008b433c in CGUIDialogSettingsBase::OnClick (this=0x327b038, pSettingControl=...) at GUIDialogSettingsBase.cpp:762
#13 0x008b6d58 in CGUIDialogSettingsBase::OnMessage (this=this@entry=0x327b038, message=...) at GUIDialogSettingsBase.cpp:208
#14 0x015845d4 in CGUIWindowSettingsCategory::OnMessage (this=0x327b038, message=...) at GUIWindowSettingsCategory.cpp:125
#15 0x00597120 in CGUIButtonControl::OnClick (this=0xa885d5b0) at GUIButtonControl.cpp:320
#16 0x00595b58 in CGUIButtonControl::OnAction (this=0xffffffff, action=...) at GUIButtonControl.cpp:152
#17 0x005040d8 in CGUIWindow::OnAction (this=0x327b038, action=...) at GUIWindow.cpp:419
#18 0x01584730 in CGUIWindowSettingsCategory::OnAction (this=<optimised out>, action=...) at GUIWindowSettingsCategory.cpp:172
#19 0x00508fac in CGUIWindowManager::OnAction (this=0x2fb5e78, action=...) at GUIWindowManager.cpp:489
#20 0x0090ccbc in CApplication::OnAction (this=0x2fb2c50, action=...) at Application.cpp:2591
#21 0x0090e3b4 in CApplication::OnKey (this=this@entry=0x2fb2c50, key=...) at Application.cpp:2506
#22 0x0090ec60 in CApplication::OnEvent (newEvent=...) at Application.cpp:475
#23 0x015a6130 in CWinEventsLinux::MessagePump (this=<optimised out>) at WinEventsLinux.cpp:66
#24 0x015a5f7c in CWinEvents::MessagePump () at WinEvents.cpp:83
#25 0x0090fc64 in CApplication::FrameMove (this=0x2fb2c50, processEvents=<optimised out>, processGUI=<optimised out>) at Application.cpp:2943
#26 0x00991338 in CXBApplicationEx::Run (this=0x2fb2c50) at XBApplicationEx.cpp:140
#27 0x00997280 in XBMC_Run (renderGUI=<optimised out>) at xbmc.cpp:69
#28 0x003d73e0 in main (argc=3, argv=0xbefff6d4) at main.cpp:76
So I think the slowness is at least partly in the speed of the network and the server. I assume you are using NFS? What are you using as the server?
I'm a little surprised that libnfs is not hitting entries in a directory cache for the exists tests. I wonder if this behaviour could have changed from an earlier xbmc version.
Reply
#6
(2015-01-17, 12:45)speedwell68 Wrote: How many videos in total? That sounds like a lot. Cleaning my database of 577 videos took quite some time. I am going to have to do it again today as the wife and I want it so the kids don't come across films that aren't really suitable. Tell us a little about your Pi.

154 movies, 48 series.
I have a Raspberry Pi RBCA000.

(2015-01-17, 13:37)popcornmix Wrote: Did you clean using a http (e.g. phone) remote app?
Is it any different when selecting "clean library" from settings/video/library?

Yes, I started the operation from my iPhone app (xbmcRemote).
But it is the same when starting the cleaning from settings/video/library.

(2015-01-17, 13:37)popcornmix Wrote: So I think the slowness is at least partly in the speed of the network and the server. I assume you are using NFS? What are you using as the server?
I'm a little surprised that libnfs is not hitting entries in a directory cache for the exists tests. I wonder if this behaviour could have changed from an earlier xbmc version.

I'm using a Synology DS214 as server. The Raspberry Pi is connecting to it through a WLAN connection via my router.
When there were ~50 movies in the database the cleaning took only seconds.
Reply
#7
(2015-01-17, 19:20)therealsega Wrote:
(2015-01-17, 12:45)speedwell68 Wrote: How many videos in total? That sounds like a lot. Cleaning my database of 577 videos took quite some time. I am going to have to do it again today as the wife and I want it so the kids don't come across films that aren't really suitable. Tell us a little about your Pi.

154 movies, 48 series.
I have a Raspberry Pi RBCA000.

How many episodes in each series? That will tell you how many videos you are processing in total. What is a Raspberry Pi RBCA000? I was thinking along the lines of Model A, A+, B or B+. Is it overclocked? What PSU do you have? Is it wireless or cabled? and so on.
HTPCs: 2 x Chromecast with Google TV
Audio: Pioneer VSX-819HK & S-HS 100 5.1 Speakers
Server: HP Compaq Pro 6300, 4GB RAM, 8.75TB, Bodhi Linux 5.x, NFS, MySQL
Reply
#8
(2015-01-17, 20:18)speedwell68 Wrote: How many episodes in each series? That will tell you how many videos you are processing in total. What is a Raspberry Pi RBCA000? I was thinking along the lines of Model A, A+, B or B+. Is it overclocked? What PSU do you have? Is it wireless or cabled? and so on.

Is there a way to automatically sum up all the episodes? Otherwise I would have to Count them manually.

I'm using a Raspberry Pi Model B which is not overclocked.
It is connected to the router with a EDIMAX EW-7811UN wirless USB stick.
What is PSU?
Reply
#9
(2015-01-20, 17:13)therealsega Wrote: I'm using a Raspberry Pi Model B which is not overclocked.
Overclock would improve speed.
Quote:It is connected to the router with a EDIMAX EW-7811UN wirless USB stick.
Using a wired ethernet connection would improve speed.
Quote:What is PSU?
Power supply unit.
Reply
#10
(2015-01-20, 17:21)popcornmix Wrote: Overclock would improve speed.
Why should overclocking improve speed if the base level of CPU usage is allready low?
It appears to me that CPU power is not the issue in this case.

(2015-01-20, 17:21)popcornmix Wrote: Using a wired ethernet connection would improve speed.
Sure about that, but not an option in my appartment.

(2015-01-20, 17:21)popcornmix Wrote: Power supply unit.
5V 1200mA
Reply
#11
(2015-01-20, 17:29)therealsega Wrote: Why should overclocking improve speed if the base level of CPU usage is allready low?
It appears to me that CPU power is not the issue in this case.
It will have some effect, but probably dwarfed by the wifi/ethernet difference
Quote:Sure about that, but not an option in my appartment.
It's worth testing (even if it means means moving the Pi temporarily).
It would be good to know if it is 10%, twice or ten times faster.
Reply

Logout Mark Read Team Forum Stats Members Help
Processing time of "Clean Database"0