Library scan causes airplay sync to go off

sticilface commented 8 years ago

Been trying to track this down for a few hours.
Play to airplay speakers stops all of a sudden.
Music continues to play in forked-daapd, just not to airplay speakers. please see this issue where i've posted verbose debug output.. from both programs

https://github.com/mikebrady/shairport-sync/issues/253

shairport-sync can't re-sync with the music... even though it is still playing. Occurs with a large lib, at or just after the lib is busy scanning / using db

ejurgensen commented 8 years ago

I'll have a look at it, but the circumstances are difficult to duplicate. I have Shairport Sync and FreeNAS (sort of), but not a very large lib. One thing to be noted is that the mechanism watching the library on FreeBSD appears to be rather inefficient. This has to do with lack of inotify on FreeBSD. As far as I can tell, this means that it is not possible to detect file changes (you already noticed this), and that when a file is added to a dir, the scanner will scan every subdir under that dir. That also involves touching up the cache, it seems.

The FreeBSD library scanning code was made before my time, so I don't really know why it is made like this. It might be possible to make something more efficient now. However, right now I don't think the combo of playback + adding files to a large library is going to work for you, especially if your FreeNAS has limited power. Maybe subdirs will be ok, but for higher dirs like your podcast dir it will set of a lot of scanning, and the server will just be too busy to also play properly.

sticilface commented 8 years ago

I can understand that, thanks for the help all the same. its weird, as the error seems to be intermittent. maybe something specific is causing it... I'm playing back an mp3 now for close to an hour and it has not stopped! I'll see if i can track it down, some more.

if a touch a file in the lib, it initiates a rescan, but it hasn't stopped playing, so no idea!

The system is pretty darn powerful, xeon quad core something fairly quick... 16gb ram... running of SSDs and 11TB of western digital 2TB REDS... so it shouldn't be that.. the system is not that taxed 0.74, 0.34, 0.24!

sticilface commented 8 years ago

There might be something else... every now and then forked-daapd stops working and the process is terminated.. but there is nothing in the log...

here is last log entry


[2016-03-28 17:03:56] [  LOG]     raop: ApEx LivingRoom New closed RTSP connection
[2016-03-28 17:03:56] [  LOG]   player: The AirPlay device 'LivingRoom New' FAILED

and from shairport-sync

Mar 28 16:03:52 rPi3 shairport-sync[3068]: Flush requested up to 1337403466. It seems as if 0 is special.
Mar 28 16:03:52 rPi3 shairport-sync[3068]: syncing to seqno 32432.
Mar 28 16:03:54 rPi3 shairport-sync[3068]: Player: packets out of sequence: expected: 32946, got: 32434, sync error: 0 frames.
Mar 28 16:03:54 rPi3 shairport-sync[3068]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 180361.
Mar 28 16:03:54 rPi3 shairport-sync[3068]: Flush requested up to 1337460490. It seems as if 0 is special.
Mar 28 16:03:54 rPi3 shairport-sync[3068]: syncing to seqno 32594.
Mar 28 16:03:55 rPi3 shairport-sync[3068]: Player: packets out of sequence: expected: 33108, got: 32596, sync error: 0 frames.
Mar 28 16:03:55 rPi3 shairport-sync[3068]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 180358.
Mar 28 16:03:55 rPi3 shairport-sync[3068]: Flush requested up to 1337517514. It seems as if 0 is special.
Mar 28 16:03:55 rPi3 shairport-sync[3068]: syncing to seqno 32756.
Mar 28 16:03:56 rPi3 shairport-sync[3068]: Player: packets out of sequence: expected: 33270, got: 32758, sync error: 0 frames.
Mar 28 16:03:56 rPi3 shairport-sync[3068]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 180365.
Mar 28 16:03:56 rPi3 shairport-sync[3068]: Flush requested up to 1337574538. It seems as if 0 is special.
Mar 28 16:03:56 rPi3 systemd[1]: shairport-sync.service: main process exited, code=killed, status=6/ABRT
Mar 28 16:03:56 rPi3 systemd[1]: Unit shairport-sync.service entered failed state.
Mar 28 16:03:56 rPi3 shairport-sync[3068]: shairport-sync: pcm.c:933: snd_pcm_state: Assertion `pcm' failed.

It seems like one or the other failed and that caused the other to die as well... Seems like there are a few issues going on here... I'll try to watch what happens if forked-daapd is running on just a rpi. ie. is all this freenas related.

mikebrady commented 8 years ago

It's pretty clear from their last log extract that Shairport Sync actually crashed after a time. That would account for forked-daapd ceasing to work....

sticilface commented 8 years ago

I should add that the time difference is due to our clocks changing recently and the freenas has not caught up just yet

ejurgensen commented 8 years ago

I did a bit of testing with Shairport Sync to see if I could provoke this, but so far no luck. I didn't get the "packets out of sequence" either. I wonder what that exactly means - do you have any ideas, @mikebrady?

I also tried killing Shairport to see if forked-daapd would die, but no "luck" with that either.

I had forked-daapd on RPi2 and Shairport on Ubuntu pc. Didn't stress forked-daapd though. I will try that later.

I did, however, encounter a problem with ipv6 and the timing/control communication between Shairport and forked-daapd. I don't think it is related to this, but if you don't mind, I will add it as an issue on your repo, Mike. I think you might be able to help solve it.

sticilface commented 8 years ago

Some more info https://github.com/mikebrady/shairport-sync/issues/253#issuecomment-202586330

if i remove all the m3u playlists it doesn't seem to do it any more... is there anything odd that does on during scan: Processing static playlist: as that is what seems to be the cause! I say tentatively as its a bit intermittent, and weird... i'd have to listen for a few days to be sure....

mikebrady commented 8 years ago

Thanks for the report. I think the "packets out of sequence" message results from a mishandling of the situation where all the buffers are empty. I've added a check for it in the latest version, so we'll see. I'll have a look at the IPv6 issue...

sticilface commented 8 years ago

i might have just got a 'big' clue.... now that i have removed m3u files i get another error entirely

[2016-03-28 22:24:07] [  LOG]     scan: Scanned 24200 files...
[2016-03-28 22:24:09] [  LOG]     scan: Scanned 24400 files...
[2016-03-28 22:24:10] [  LOG]     scan: Processing static playlist: /mnt/media/My Music/HiDefALBUMS/Dire Straits, Mark Knopfler - Private Investigations- The Best of Dire Straits & Mark Knopfler (2008)/DIREST~1.M3U
[2016-03-28 22:24:11] [  LOG]     scan: Processing static playlist: /mnt/media/My Music/ALBUMS/Joanna Newsom and the Ys Street Band - Joanna Newsom and the Ys Street Band E.P. [2007]/playlist.pls
[2016-03-28 22:24:11] [  LOG]     scan: Bulk library scan completed in 56 sec
[2016-03-28 22:27:23] [  LOG]     scan: Processing static playlist: /mnt/media/My Music/ALBUMS/Joanna Newsom and the Ys Street Band - Joanna Newsom and the Ys Street Band E.P. [2007]/playlist.pls
[2016-03-28 22:28:29] [  LOG]       db: Query error: step failed: unable to open database file
[2016-03-28 22:28:29] [  LOG]       db: Insert or update of directory failed '/file:/mnt/media/My Music/ALBUMS/Joss Stone - The Soul Sessions, Volume 2 [2012]'
[2016-03-28 22:28:29] [  LOG]     scan: Insert or update of directory failed '/file:/mnt/media/My Music/ALBUMS/Joss Stone - The Soul Sessions, Volume 2 [2012]'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11181;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11182;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11183;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11184;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11185;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11186;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11187;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11188;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11189;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11190;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11191;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11192;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11193;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11194;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'UPDATE files SET db_timestamp = 1459200509, disabled = 0 WHERE id = 11195;'
[2016-03-28 22:28:29] [  LOG]       db: Error 'step failed: unable to open database file' while runnning 'INSERT INTO inotify (wd, cookie, path) VALUES (10268, 0, '/mnt/media/My Music/ALBUMS/Joss Stone - The Soul Sessions, Volume 2 [2012]');'
[2016-03-28 22:28:29] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/The Big Lebowski - The Big Lebowski Soundtrack (1995): Too many open files in system

this could explain everything.... a freebsd thing...

sticilface commented 8 years ago

fstat.txt Does this look right to you? I think there are far too many open files for forked-daapd? my count puts this at over 10,000

although I'm not sure what is going on under the hood but it seems like a lot. with scanning enabled at start up this number just keeps climbing. with scanning disabled it sits at 3150.. and doesn't climb

ejurgensen commented 8 years ago

That may be the consequence of FreeBSD not having inotify. See: https://forums.freebsd.org/threads/38162/

However, 10 000 directories for a library of 24 400 files does sound too high. 3150 sounds more reasonable. I don’t know if some may be getting added twice? Perhaps you could do the following:

sqlite3 [your forked-daapd database]
run “select count(*) from inotify;” -> what does that say? should be about the same 10k
run “select path, count(path) from inotify group by path having (count(path) > 1);” -> should give you dirs that have been duplicates, if any

If the problem is duplicates then I think I can fix it. Otherwise the only “solution” I can think of is adding a config option to disable live watching of your library. Well, it would still watch the root, so you can do pairings and so on, but not the subdirs. Then you would need to use the init-rescan feature with cron (see the README) to make forked-daapd update library changes.

sticilface commented 8 years ago

ok i've done that... based on what you said and because i've added and moved the folder structures around a bit i decided to place a .full-rescan file in the main directory whilst watching what was happening... dumps are below... but what happened... was interesting...

1) scan started immediately 2) select count(*) from notify; started at 100 and kept rising constantly to around 3000. 3) the fstat for forked-daapd started at 3000 and rose to 6000. if i kill forked it goes to zero. i didn't do that before starting the rescan. 4) the scan finished... 5) the scan started again.. cpu was still high.. all the numbers kept climbing... database command 2...
6) the log for forked... is saying processing static lists... i only have two... 7) NOW when i run your sqlite command 3... i get screen full of entries whereas before i got nothing...

Forked log

root@forked-daapd:/ # tail -f /var/log/forked-daapd.log
[2016-03-29 16:49:45] [  LOG]     scan: Scanned 11400 files...
[2016-03-29 16:49:50] [  LOG]     scan: Scanned 11600 files...
[2016-03-29 16:49:56] [  LOG]     scan: Scanned 11800 files...
[2016-03-29 16:50:02] [  LOG]     scan: Scanned 12000 files...
[2016-03-29 16:50:08] [  LOG]     scan: Scanned 12200 files...
[2016-03-29 16:50:13] [  LOG]     scan: Scanned 12400 files...
[2016-03-29 16:50:17] [  LOG]     scan: Scanned 12600 files...
[2016-03-29 16:50:22] [  LOG]     scan: Scanned 12800 files...
[2016-03-29 16:50:26] [  LOG]     scan: Scanned 13000 files...
[2016-03-29 16:50:32] [  LOG]     scan: Scanned 13200 files...
[2016-03-29 16:50:38] [  LOG]     scan: Scanned 13400 files...
[2016-03-29 16:50:43] [  LOG]     scan: Scanned 13600 files...
[2016-03-29 16:50:48] [  LOG]     scan: Scanned 13800 files...
[2016-03-29 16:50:55] [  LOG]     scan: Scanned 14000 files...
[2016-03-29 16:51:02] [  LOG]     scan: Scanned 14200 files...
[2016-03-29 16:51:07] [  LOG]     scan: Scanned 14400 files...
[2016-03-29 16:51:12] [  LOG]     scan: Scanned 14600 files...
[2016-03-29 16:51:17] [  LOG]     scan: Scanned 14800 files...
[2016-03-29 16:51:30] [  LOG]     scan: Scanned 15000 files...
[2016-03-29 16:51:34] [  LOG]     scan: Scanned 15200 files...
[2016-03-29 16:51:38] [  LOG]     scan: Scanned 15400 files...
[2016-03-29 16:51:42] [  LOG]     scan: Scanned 15600 files...
[2016-03-29 16:51:49] [  LOG]     scan: Scanned 15800 files...
[2016-03-29 16:51:55] [  LOG]     scan: Scanned 16000 files...
[2016-03-29 16:52:01] [  LOG]     scan: Scanned 16200 files...
[2016-03-29 16:52:05] [  LOG]     scan: Scanned 16400 files...
[2016-03-29 16:52:09] [  LOG]     scan: Scanned 16600 files...
[2016-03-29 16:52:13] [  LOG]     scan: Scanned 16800 files...
[2016-03-29 16:52:18] [  LOG]     scan: Scanned 17000 files...
[2016-03-29 16:52:23] [  LOG]     scan: Scanned 17200 files...
[2016-03-29 16:52:28] [  LOG]     scan: Scanned 17400 files...
[2016-03-29 16:52:33] [  LOG]     scan: Scanned 17600 files...
[2016-03-29 16:52:37] [  LOG]     scan: Scanned 17800 files...
[2016-03-29 16:52:41] [  LOG]     scan: Scanned 18000 files...
[2016-03-29 16:52:46] [  LOG]     scan: Scanned 18200 files...
[2016-03-29 16:52:51] [  LOG]     scan: Scanned 18400 files...
[2016-03-29 16:52:56] [  LOG]     scan: Scanned 18600 files...
[2016-03-29 16:53:01] [  LOG]     scan: Scanned 18800 files...
[2016-03-29 16:53:06] [  LOG]     scan: Scanned 19000 files...
[2016-03-29 16:53:11] [  LOG]     scan: Scanned 19200 files...
[2016-03-29 16:53:17] [  LOG]     scan: Scanned 19400 files...
[2016-03-29 16:53:25] [  LOG]     scan: Scanned 19600 files...
[2016-03-29 16:53:33] [  LOG]     scan: Scanned 19800 files...
[2016-03-29 16:53:53] [  LOG]     scan: Scanned 20000 files...
[2016-03-29 16:54:05] [  LOG]     scan: Scanned 20200 files...
[2016-03-29 16:54:08] [  LOG]   ffmpeg: No JPEG data found in image
[2016-03-29 16:54:15] [  LOG]     scan: Scanned 20400 files...
[2016-03-29 16:54:23] [  LOG]     scan: Scanned 20600 files...
[2016-03-29 16:54:31] [  LOG]     scan: Scanned 20800 files...
[2016-03-29 16:54:39] [  LOG]     scan: Scanned 21000 files...
[2016-03-29 16:54:56] [  LOG]     scan: Scanned 21200 files...
[2016-03-29 16:55:07] [  LOG]     scan: Scanned 21400 files...
[2016-03-29 16:55:13] [  LOG]     scan: Scanned 21600 files...
[2016-03-29 16:55:20] [  LOG]     scan: Scanned 21800 files...
[2016-03-29 16:55:28] [  LOG]     scan: Scanned 22000 files...
[2016-03-29 16:55:37] [  LOG]     scan: Scanned 22200 files...
[2016-03-29 16:55:43] [  LOG]     scan: Scanned 22400 files...
[2016-03-29 16:55:51] [  LOG]     scan: Scanned 22600 files...
[2016-03-29 16:56:01] [  LOG]     scan: Scanned 22800 files...
[2016-03-29 16:56:08] [  LOG]     scan: Scanned 23000 files...
[2016-03-29 16:56:15] [  LOG]     scan: Scanned 23200 files...
[2016-03-29 16:56:24] [  LOG]     scan: Scanned 23400 files...
[2016-03-29 16:56:30] [  LOG]     scan: Scanned 23600 files...
[2016-03-29 16:56:38] [  LOG]     scan: Scanned 23800 files...
[2016-03-29 16:56:46] [  LOG]     scan: Scanned 24000 files...
[2016-03-29 16:56:53] [  LOG]     scan: Scanned 24200 files...
[2016-03-29 16:57:00] [  LOG]     scan: Scanned 24400 files...
[2016-03-29 16:57:16] [  LOG]     scan: Processing static playlist: /mnt/media/My Music/HiDefALBUMS/Dire Straits, Mark Knopfler - Private Investigations- The Best of Dire Straits & Mark Knopfler (2008)/DIREST~1.M3U
[2016-03-29 16:57:17] [  LOG]     scan: Processing static playlist: /mnt/media/My Music/ALBUMS/Joanna Newsom and the Ys Street Band - Joanna Newsom and the Ys Street Band E.P. [2007]/playlist.pls
[2016-03-29 16:57:17] [  LOG]     scan: Bulk library scan completed in 733 sec
[2016-03-29 17:01:00] [  LOG]     scan: Processing static playlist: /mnt/media/My Music/ALBUMS/Joanna Newsom and the Ys Street Band - Joanna Newsom and the Ys Street Band E.P. [2007]/playlist.pls
[2016-03-29 17:07:24] [  LOG]       db: Error 'step failed: database is locked' while runnning 'INSERT INTO inotify (wd, cookie, path) VALUES (8781, 0, '/mnt/media/My Music/ALBUMS/The Smiths');'
[2016-03-29 17:07:24] [  LOG]       db: Query error: step failed: database is locked
[2016-03-29 17:07:24] [  LOG]       db: Insert or update of directory failed '/file:/mnt/media/My Music/ALBUMS/The Smiths/The Smiths'
[2016-03-29 17:07:24] [  LOG]     scan: Insert or update of directory failed '/file:/mnt/media/My Music/ALBUMS/The Smiths/The Smiths'
[2016-03-29 17:11:05] [  LOG]     scan: Processing static playlist: /mnt/media/My Music/HiDefALBUMS/Dire Straits, Mark Knopfler - Private Investigations- The Best of Dire Straits & Mark Knopfler (2008)/DIREST~1.M3U

SQLITE dumps

SQLite version 3.11.1 2016-03-03 16:17:53
Enter ".help" for usage hints.
sqlite> select count(*) from inotify;
3097
sqlite> select path, count(path) from inotify group by path having (count(path) > 1);
sqlite> select count(*) from inotify;
138
sqlite> select path, count(path) from inotify group by path having (count(path) > 1);
sqlite> select path, count(path) from inotify group by path having (count(path) > 1);
sqlite> select count(*) from inotify;
183
sqlite> select count(*) from inotify;
202
sqlite> select count(*) from inotify;
202
sqlite> select count(*) from inotify;
816
sqlite> select count(*) from inotify;
845
sqlite> select path, count(path) from inotify group by path having (count(path) > 1);
sqlite> select path, count(path) from inotify group by path having (count(path) > 1);
sqlite> select count(*) from inotify;
2261
sqlite> select count(*) from inotify;
2660
sqlite> select count(*) from inotify;
2940
sqlite> select count(*) from inotify;
2956
sqlite> select count(*) from inotify;
2956
sqlite> select count(*) from inotify;
2956
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
3335
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
Error: database is locked
sqlite> select count(*) from inotify;
5590
sqlite> select path, count(path) from inotify group by path having (count(path) > 1);
Error: database is locked
sqlite> select path, count(path) from inotify group by path having (count(path) > 1);
Error: database is locked
sqlite> select path, count(path) from inotify group by path having (count(path) > 1);
/mnt/media/My Music/ALBUMS|2
/mnt/media/My Music/ALBUMS/50 Cent - The Massacre|2
/mnt/media/My Music/ALBUMS/80's Night (DJ Collections)|2
/mnt/media/My Music/ALBUMS/80's Night (DJ Collections)/01|2
/mnt/media/My Music/ALBUMS/80's Night (DJ Collections)/02|2
/mnt/media/My Music/ALBUMS/80's Night (DJ Collections)/03|2
/mnt/media/My Music/ALBUMS/80's Night (DJ Collections)/04|2
/mnt/media/My Music/ALBUMS/80's Night (DJ Collections)/05|2
etc....

fstat dump

root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    3280
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    3992
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    4086
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    5417
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    5908
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    6090
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    6136
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    6142
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    6310
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    6538
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    7057
root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
    9343
root@forked-daapd:~/daapd #

sticilface commented 8 years ago

so it looks like...

the file open count keeps climbing. even once the initial scan should be done... the database is updating creating duplicates...

it seems like it then stops after this with the following stats.. which are stable.. i think if i initiate a scan it will fall over... not tried that

1) select count(*) from notify = 6190 2) fstat | grep forked-daapd | wc -l = 9343 3) your third sql query gives a whole page of entries.

so it seems like if all this kicks of during streaming that there is a problem...

sticilface commented 8 years ago

Last bit of info... left it for a bit and it was stable, played music.. initiated a scan with init-rescan and

sqlite number reset...

sqlite> select count(*) from inotify;
368
sqlite> select count(*) from inotify;
816

however the files open kept climbing.

root@forked-daapd:~/daapd # fstat | grep forked-daapd | wc -l
   10227

then forked-daapd started complaining

[2016-03-29 18:12:22] [  LOG]     scan: Startup rescan triggered, found init-rescan file: /root/daapd/trigger.init-rescan
[2016-03-29 18:12:22] [  LOG]     scan: Startup rescan triggered
[2016-03-29 18:12:22] [  LOG]   remote: Read Remote pairing data (name 'Andrew's iPhone', pin '6455') from /root/daapd/am.remote
[2016-03-29 18:12:22] [  LOG]   remote: Remote 'Andrew's iPhone' not known from mDNS, ignoring
[2016-03-29 18:12:22] [  LOG]   remote: Read Remote pairing data (name 'D6603', pin '2689') from /root/daapd/kh.remote
[2016-03-29 18:12:22] [  LOG]   remote: Remote 'D6603' not known from mDNS, ignoring
[2016-03-29 18:12:23] [  LOG]     scan: Scanned 200 files...
[2016-03-29 18:12:23] [  LOG]     scan: Scanned 400 files...
[2016-03-29 18:12:23] [  LOG]     scan: Scanned 600 files...
[2016-03-29 18:12:24] [  LOG]     scan: Scanned 800 files...
[2016-03-29 18:12:24] [  LOG]     scan: Scanned 1000 files...
[2016-03-29 18:12:24] [  LOG]     scan: Scanned 1200 files...
[2016-03-29 18:12:24] [  LOG]     scan: Scanned 1400 files...
[2016-03-29 18:12:24] [  LOG]     scan: Scanned 1600 files...
[2016-03-29 18:12:25] [  LOG]     scan: Scanned 1800 files...
[2016-03-29 18:12:25] [  LOG]     scan: Scanned 2000 files...
[2016-03-29 18:12:26] [  LOG]     scan: Scanned 2200 files...
[2016-03-29 18:12:26] [  LOG]     scan: Scanned 2400 files...
[2016-03-29 18:12:26] [  LOG]     scan: Scanned 2600 files...
[2016-03-29 18:12:26] [  LOG]     scan: Scanned 2800 files...
[2016-03-29 18:12:27] [  LOG]     scan: Scanned 3000 files...
[2016-03-29 18:12:27] [  LOG]     scan: Scanned 3200 files...
[2016-03-29 18:12:27] [  LOG]     scan: Scanned 3400 files...
[2016-03-29 18:12:27] [  LOG]     scan: Scanned 3600 files...
[2016-03-29 18:12:28] [  LOG]     scan: Scanned 3800 files...
[2016-03-29 18:12:28] [  LOG]     scan: Scanned 4000 files...
[2016-03-29 18:12:29] [  LOG]     scan: Scanned 4200 files...
[2016-03-29 18:12:29] [  LOG]     scan: Scanned 4400 files...
[2016-03-29 18:12:29] [  LOG]     scan: Scanned 4600 files...
[2016-03-29 18:12:29] [  LOG]     scan: Scanned 4800 files...
[2016-03-29 18:12:30] [  LOG]     scan: Scanned 5000 files...
[2016-03-29 18:12:30] [  LOG]     scan: Scanned 5200 files...
[2016-03-29 18:12:30] [  LOG]     scan: Scanned 5400 files...
[2016-03-29 18:12:31] [  LOG]     scan: Scanned 5600 files...
[2016-03-29 18:12:31] [  LOG]     scan: Scanned 5800 files...
[2016-03-29 18:12:31] [  LOG]     scan: Scanned 6000 files...
[2016-03-29 18:12:32] [  LOG]     scan: Scanned 6200 files...
[2016-03-29 18:12:32] [  LOG]     scan: Scanned 6400 files...
[2016-03-29 18:12:32] [  LOG]     scan: Scanned 6600 files...
[2016-03-29 18:12:32] [  LOG]     scan: Scanned 6800 files...
[2016-03-29 18:12:33] [  LOG]     scan: Scanned 7000 files...
[2016-03-29 18:12:34] [  LOG]     scan: Scanned 7200 files...
[2016-03-29 18:12:34] [  LOG]     scan: Scanned 7400 files...
[2016-03-29 18:12:34] [  LOG]     scan: Scanned 7600 files...
[2016-03-29 18:12:34] [  LOG]     scan: Scanned 7800 files...
[2016-03-29 18:12:35] [  LOG]     scan: Scanned 8000 files...
[2016-03-29 18:12:35] [  LOG]     scan: Scanned 8200 files...
[2016-03-29 18:12:35] [  LOG]     scan: Scanned 8400 files...
[2016-03-29 18:12:36] [  LOG]     scan: Scanned 8600 files...
[2016-03-29 18:12:36] [  LOG]     scan: Scanned 8800 files...
[2016-03-29 18:12:37] [  LOG]     scan: Scanned 9000 files...
[2016-03-29 18:12:37] [  LOG]     scan: Scanned 9200 files...
[2016-03-29 18:12:37] [  LOG]     scan: Scanned 9400 files...
[2016-03-29 18:12:37] [  LOG]     scan: Scanned 9600 files...
[2016-03-29 18:12:38] [  LOG]     scan: Scanned 9800 files...
[2016-03-29 18:12:38] [  LOG]     scan: Scanned 10000 files...
[2016-03-29 18:12:38] [  LOG]     scan: Scanned 10200 files...
[2016-03-29 18:12:39] [  LOG]     scan: Scanned 10400 files...
[2016-03-29 18:12:39] [  LOG]     scan: Scanned 10600 files...
[2016-03-29 18:12:39] [  LOG]     scan: Scanned 10800 files...
[2016-03-29 18:12:39] [  LOG]     scan: Scanned 11000 files...
[2016-03-29 18:12:40] [  LOG]     scan: Scanned 11200 files...
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Midlake - Bamnan & Slivercork (2004): Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/The Black Eyed Peas - Elephunk [2003]: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Sum 41 - All Killer No Filler (2001): Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Krezip - Nothing Less: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Queen - Made in Heaven: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Nightmares On Wax - Smokers Delight: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Shiny Toy Guns - We Are Pilots (2006): Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/EELS - Oh What a Beautiful Morning [2000]: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Phil Woods - Piper at the Gates of Dawn [1986]: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/The Jackson 5 - The Ultimate Collection [CASSETTE] (1996): Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Enya - A Day Without Rain: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/London Grammar - Strong [2013]: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/EELS - Eels With Strings_ Live at Town Hall [2006]: Too many open files in system
[2016-03-29 18:12:40] [  LOG]     scan: Could not open directory /mnt/media/My Music/ALBUMS/Faint - Danse Macabre (2001): Too many open files in system

ejurgensen commented 8 years ago

I had another look at the FreeBSD library scanning code, and I can see there are a couple of issues that I need to look at.

Among the issues is that init-rescan and full-rescan are broken on FreeBSD, as you have observed. So avoid them for now. You can, however, trigger something very much like an init-rescan by placing any file in the library root. The file can be empty too. As far as I can tell, this will currently trigger a complete rescan. Just don’t call the file init-rescan, because then a double scan starts, and you get duplicates.

sticilface commented 8 years ago

OK,

that all makes sense. it seems to make it a bit unreliable. Do you think these issues are still around in freebsd 10?

how 'solvable' do you think they are?

I deleted the database and started again, but even without calling init anything the number of open files still climbs to over 9000... seeing as my system goes a bit nuts at 10000... that is a bit close. is that many still normal? without calling a rescan?

Thanks for all the help btw.

ejurgensen commented 8 years ago

Yes, the same issues will be there in FreeBSD 10. Right now there is not so much you can do, unfortunately.

I don't think the 9000 open files is right. There seems to be more than one bug to squash. I am fairly sure it is solvable, but there are different ways of doing that. I am thinking about what the best way would be. Right now it is hard to say when I can have it fixed, but if the easy solution I am thinking of pans out then probably within a week.

sticilface commented 8 years ago

that sounds great, and if it will exist in bsd 10 then it worth fixing. Let me know if there is anything i can help out with. Have you recreated a similar thing with far too many open files?

freultwah commented 8 years ago

As a temporary workaround, you can increase the maximum number of open files in /etc/sysctl.conf:

kern.maxfiles=204800 kern.maxfilesperproc=200000 kern.maxvnodes=200000

This is from my FreeBSD machine with 4 GiB of RAM. (Edit: Probably lifted the settings from http://serverfault.com/questions/64356/freebsd-performance-tuning-sysctl-parameter-loader-conf-kernel)

freultwah commented 8 years ago

I just checked how many files are open on a relatively idle system with forked-daapd just running, not scanning. I've got 1500 directories in the music library, and I am also running a web server, mail server, and some other minor services on it. lsof reports ~6500 open files, of which more than 2000 belong to forked-daapd. (The list consists largely of linked libraries and directories that count as files.) So it's not out of the question that the scanning process temporarily increases the number to over 10,000, and the limit of 10,000 open files is really on the very conservative side and should be increased manyfold.

ejurgensen commented 8 years ago

If you don't mind being a guinea pig you are more than welcome to try the freebsd3 branch: https://github.com/ejurgensen/forked-daapd/tree/freebsd3

Here I am working on using libinotify for FreeBSD. Right now that seems like the best way to make the filescanner support FreeBSD. It gives an extra dependency, but all that is required is to “pkg install libinotify”. It is available for FreeBSD 9 too.

You should see that the number of open files is greatly reduced, since this method only opens directories. You should also have special files like init-rescan working without triggering double scans.

Currently not working: Files and directories being renamed, directories being deleted.

sticilface commented 8 years ago

I don't mind at all! away from home for a while, so can't test, but will do when i get a chance! Thanks for the work!

ejurgensen commented 8 years ago

I think the basics are alright now. I've gone ahead and merged the changes into master, since I am pretty sure they will be an improvement over the previous, even if there might still be some kinks. Note that file modifications will not be detected, and there is not much I can do about that without having the files open.

ejurgensen commented 8 years ago

A few extra remarks concerning FreeBSD: When testing with FreeBSD I encountered segfaults when playback stopped. I have added a fix for that. I have also merged a major change, which removes OSS4 support. So that means you must now use ALSA on FreeBSD if you want local audio. Later, I expect to add Pulseaudio.

While OSS4 has been removed, ALSA has been reworked, and when I tested with ALSA on FreeBSD it worked fine. So I hope that will also be your experience.

sticilface commented 8 years ago

This sounds fantastic. Thank you. I have been experiencing crashes when playback stopped. But was not so sure it was a bug. Plus I kept you busy enough!

I shall hopefully be home to test this weekend.

Thanks again for all the work!

mikebrady commented 8 years ago

Thanks for all this. I hope I'm still right in thinking it's not related to Shairport Sync...

The "buffer out of sequence" message from Shairport Sync, mentioned in https://github.com/ejurgensen/forked-daapd/issues/245#issuecomment-202587687, was indeed caused by misreporting a buffers-empty condition and was benign. The IPv6 issue definitely would not cause the problems mentioned here and is being addressed [slowly].

ejurgensen commented 8 years ago

Yes, I believe it is not related to Shairport Sync. But good to hear that you found a way of getting the announce IP from Avahi!

@sticilface, I'm looking forward to hearing how it works now with your large library.

sticilface commented 8 years ago

Hi,

Ok so came home, and recompiled and installed. All seems fine. started lib, scaned all the files thats fine.. connecting with remote.. failed..

tried repairing.. still failed. Its picked up by forked-daapd when i try to pair, it picks the .remote file up straight away. but when i try to open the lib, it just hangs. There is no log output by forked-daapd even in debug mode. tried twice.

any ideas?

ejurgensen commented 8 years ago

I didn't change any of this, so this is likely something else. Well at least if forked-daapd is still running? If there is no log output, and it is still running, then it did not get any request from Remote. So some network issue. Can you try with another Remote? For good measure, you could also try with ipv6 disabled.

Occasionally, I get something like you described. Only on my dev machine (never the RPi), and only with iPhone's Remote (never the iPad's). After a while it works again. Never found the cause.

If it is crashing then it is another story, so that would be interesting to know.

sticilface commented 8 years ago

No crash. Just not responding. Kinda wierd as it connects to my iTunes just fine. I'll reset everything.

ejurgensen commented 8 years ago

Mine pairs ok, tested both FreeNAS and FreeBSD. For some reason I needed to wait a bit (like 30 sec), before the connection was made. If you didn't already, have a look at the troubleshooting guide in the README. You are also welcome to post the debug log from the pairing and afterwards, maybe that reveals something. lør. 16. apr. 2016 kl. 11.04 skrev sticilface notifications@github.com:

No crash. Just not responding. Kinda wierd as it connects to my iTunes just fine. I'll reset everything.

— You are receiving this because you commented.

Reply to this email directly or view it on GitHub https://github.com/ejurgensen/forked-daapd/issues/245#issuecomment-210777835

sticilface commented 8 years ago

my lib doesn't load using iTunes either, I think the database might be corrupt. although it cleans ok. I will recreate it! see if that helps.

sticilface commented 8 years ago

OK, I started from scratch and that seems to have fixed it. I'll let you know how it all works out. Thanks for the help and for supporting freebsd!

sticilface commented 8 years ago

Preliminary report: All seems to be a lot more stable! very good thank you.

ejurgensen commented 8 years ago

Thanks for the feedback, I hope that also means you got Remote paired and that the original AirPlay problem is resolved.

sticilface commented 8 years ago

Yes. I did solve that problem. just reinstalled.

sticilface commented 8 years ago

Just wanted to say thanks. your hard work has paid of and it has been working pretty much flawlessly since. :)

owntone / owntone-server

Library scan causes airplay sync to go off #245