Slimserver and Moodlogic not playing nicely anf throwingtheir toys out of the pram

[Adam White]

I've been doing some further investigation into my MoodLogic problems and have tried various things and made a few discoveries.

My Setup: Win Xp Home SP2, 2.6 Celeron (640 MB) 2*200 GB disc for storing WMA lossless, aprox 15k tracks along with wired squeezebox.

Firstly, I've loaded a very recent 6.0 to see how performance is affected. On the whole I'm very happy, a lot more responsive and a smaller memory footprint, which is great! (although a few general problems still to sort out)

My first observation:
When adding tracks to MusicLogic, slim.exe immediately notices that tracks have changed and start competing with MoodLogic for CPU. This results in a near locked up machine, whichever one wins seems to be a bit of luck. Moodlogic happily (but now slowly) adding song's to it's database. When they have all been added and it starts activiation, slim.exe goes into terminal decline.
I retrieved the following from the log....
2005-01-02 20:28:38.4735 using moodlogic: 1
2005-01-02 20:28:38.4742 music library has changed!
Use of uninitialized value in subtraction (-) at /PerlApp/Slim/Music/MoodLogic.pm line 144.
2005-01-02 20:28:38.4746 using moodlogic: 1
2005-01-02 20:28:38.4747 startScan: start export
2005-01-02 20:28:38.4753 using moodlogic: 1
2005-01-02 20:28:42.1084 Found MoodLogic Auto Playlist: moodlogicplaylist:%2BRock%20(Slow)
2005-01-02 20:28:46.8975 adding 644 items
etc etc.....
2005-01-02 20:33:50.9865 Found MoodLogic Auto Playlist: moodlogicplaylist:%2BRock%20%5BUpbeat%5D
2005-01-02 20:33:58.4439 adding 564 items
2005-01-02 20:34:17.7621 OLE exception from "Microsoft OLE DB Provider for ODBC Drivers":

[Microsoft][ODBC Microsoft Access Driver] Record is deleted.

Win32::OLE(0.1701) error 0x80004005: "Unspecified error"
in METHOD/PROPERTYGET "MoveNext"
2005-01-02 20:34:17.7647 Found MoodLogic Auto Playlist: moodlogicplaylist:%2BRock%20%5BHappy%5D
2005-01-02 20:34:17.7700 OLE exception from "Microsoft OLE DB Provider for ODBC Drivers":

[Microsoft][ODBC Microsoft Access Driver] Record is deleted.

Win32::OLE(0.1701) error 0x80004005: "Unspecified error"
in METHOD/PROPERTYGET "MoveNext"
2005-01-02 20:34:17.7741 OLE exception from "Microsoft OLE DB Provider for ODBC Drivers":

[Microsoft][ODBC Microsoft Access Driver] Record is deleted.

This then repeats for the next 240 MB until I decide to end the process. (If I didn't do this, it would eventally die after using 2GB of swap space).


To me, this seems to be a clash which could partially be resolved by not loading moodlogica data quite so immeditely. I personally would like the re-scan to happen on demand, in the same way as a slimserver rescan is requested.
----
Second Observation:
On 6.0 when rescanning (in my case at 03:00), slim.exe dies: (here's the last few lines of the log)
Malformed UTF-8 character (unexpected non-continuation byte 0x6f, immediately after start byte 0xe3) in substitution (s///) at /PerlApp/URI/file/Base.pm line 31.
Malformed UTF-8 character (unexpected non-continuation byte 0x6f, immediately after start byte 0xe3) in substitution (s///) at /PerlApp/URI/file/Base.pm line 31.
Malformed UTF-8 character (unexpected non-continuation byte 0x6f, immediately after start byte 0xe3) in substitution (s///) at /PerlApp/URI.pm line 40.
Malformed UTF-8 character (unexpected non-continuation byte 0x6f, immediately after start byte 0xe3) in substitution iterator at /PerlApp/URI.pm line 76.
Malformed UTF-8 character (unexpected non-continuation byte 0x6f, immediately after start byte 0xe3) in substitution iterator at /PerlApp/URI.pm line 76.
Malformed UTF-8 character (unexpected non-continuation byte 0x6f, immediately after start byte 0xe3) in substitution iterator at /PerlApp/URI.pm line 76.
[F:\Music\Various Artists\Best Latino Carnival Album in the World Ever Disc 2\14 N?o Chore Mais (No Woman No Cry).wma] does not exist or cannot be read: Invalid argument at /PerlApp/Audio/WMA.pm line 30.
2005-01-03 03:08:56.1235 using moodlogic: 1
2005-01-03 03:09:01.1276 using moodlogic: 1
Can't use an undefined value as an ARRAY reference at /PerlApp/Slim/Utils/Scan.pm line 194.

----
Third observation:
I notice that the track numbers when using MoodLogic are out by one. It seems looking the the moodlogic database that the track numbering starts at zero, whereas in real life they start at one. Without Moodlocig, all is correct.

----
I hope this proves useful!

Cheers
Adam

[kdf]

Quoting Adam White <adam (AT) AdamAndLiz (DOT) com>:


> My first observation:
> When adding tracks to MusicLogic, slim.exe immediately notices that
> tracks have changed and start competing with MoodLogic for CPU. This results
> in a near locked up machine, whichever one wins seems to be a bit of luck.
> Moodlogic happily (but now slowly) adding song's to it's database. When they
> have all been added and it starts activiation, slim.exe goes into terminal
> decline.

> To me, this seems to be a clash which could partially be resolved by not
> loading moodlogica data quite so immeditely. I personally would like the
> re-scan to happen on demand, in the same way as a slimserver rescan is
> requested.

fortunately, if you look in server settings, under the moodlogic page, you can
set the moodlogic rescan interval. Any changes wil not trigger a rescan until
that interval (in seconds) has passed since the last scan.

> Second Observation:
> Can't use an undefined value as an ARRAY reference at
> /PerlApp/Slim/Utils/Scan.pm line 194.

this is a common error message, reported by many users. likely nothing to do
with moodlogic use.

> ----
> Third observation:
> I notice that the track numbers when using MoodLogic are out by one. It
> seems looking the the moodlogic database that the track numbering starts at
> zero, whereas in real life they start at one. Without Moodlocig, all is
> correct.

that's not one that I've noticed, but easy enough to confirm. I'll work up a
patch, if I can reproduced it.

-kdf

[Adam White]

Thanks for the exceedingly prompt reply!

----- Original Message -----
From: "kdf" <slim-mail (AT) deane-freeman (DOT) com>
To: "Slim Devices Discussion" <discuss (AT) lists (DOT) slimdevices.com>
Sent: Monday, January 03, 2005 11:03 AM

> fortunately, if you look in server settings, under the moodlogic page, you
> can
> set the moodlogic rescan interval. Any changes wil not trigger a rescan
> until
> that interval (in seconds) has passed since the last scan.
>
I see that, however I tend to load new tunes up on a random basis (currently
nearly daily). I let the scan go ahead at 3am and then later on I decide to
refresh moodlogic. Looking at the log:
2005-01-02 20:28:38.4742 music library has changed!
Use of uninitialized value in subtraction (-) at
/PerlApp/Slim/Music/MoodLogic.pm line 144.
it seems that it is totally ignoring the last time the moodlogic rescan took
place (my perl isn't up to much so I may be mis interpretting this here)

Whilst all of this is going on, the web interface is totally non-responsive
and the squeezebox becomes about as useful as a chocolate tea-pot! When
you've got a SWMBO who is going back to use CD's because the SB simply does
not work for hours on end, I'm sure you appreciate my predicament!

Anyway, my point being that I would like to hold off on the moodlogic
re-scan until moodlogic has done all it's stuff; as it seems the two running
together is causing the terminal behaviour of slim.exe (BTW i noticed this
in 5.4 as well)

[kdf]

Quoting Adam White <adam (AT) AdamAndLiz (DOT) com>:

> Thanks for the exceedingly prompt reply!
>
> ----- Original Message -----
> From: "kdf" <slim-mail (AT) deane-freeman (DOT) com>
> To: "Slim Devices Discussion" <discuss (AT) lists (DOT) slimdevices.com>
> Sent: Monday, January 03, 2005 11:03 AM
>
> > fortunately, if you look in server settings, under the moodlogic page, you
> > can
> > set the moodlogic rescan interval. Any changes wil not trigger a rescan
> > until
> > that interval (in seconds) has passed since the last scan.
> >
> I see that, however I tend to load new tunes up on a random basis (currently
> nearly daily). I let the scan go ahead at 3am and then later on I decide to
> refresh moodlogic. Looking at the log:
> 2005-01-02 20:28:38.4742 music library has changed!
> Use of uninitialized value in subtraction (-) at
> /PerlApp/Slim/Music/MoodLogic.pm line 144.
> it seems that it is totally ignoring the last time the moodlogic rescan took
> place (my perl isn't up to much so I may be mis interpretting this here)
>
Did you restart the server at any point in between? When the scan completes,
the time should then be stored, but if the server were to be restarted, this
time record is not kept.

> Whilst all of this is going on, the web interface is totally non-responsive
> and the squeezebox becomes about as useful as a chocolate tea-pot! When
> you've got a SWMBO who is going back to use CD's because the SB simply does
> not work for hours on end, I'm sure you appreciate my predicament!

I honestly can't. But that doesn't mean there isn't something that should be
fixed in here.

> Anyway, my point being that I would like to hold off on the moodlogic
> re-scan until moodlogic has done all it's stuff; as it seems the two running
> together is causing the terminal behaviour of slim.exe (BTW i noticed this
> in 5.4 as well)

There is room to improve the moodlogic scan so that it doesn't take over.
Currently the entire scan is done in one shot. This can get overwhelming for
any library of some size. It can be broken down to allow the scheduler to
control the scan. This releases some cpu time for other tasks, but also takes
longer to scan. This same method was used for the MusicMagic scanning in the
6.0 builds.

-kdf

[Adam White]

----- Original Message -----
From: "kdf" <slim-mail (AT) deane-freeman (DOT) com>
To: "Slim Devices Discussion" <discuss (AT) lists (DOT) slimdevices.com>
Sent: Monday, January 03, 2005 6:15 PM
Subject: [slim] Slimserver and Moodlogic not playing nicely
anfthrowingtheir toys out of the pram
> Did you restart the server at any point in between? When the scan
> completes,
> the time should then be stored, but if the server were to be restarted,
> this
> time record is not kept.
>
Yes, I would have re-started both after it failed at the 3am re-scan and
after it went wild when adding tracks to moodlogic.

>
> There is room to improve the moodlogic scan so that it doesn't take over.
> Currently the entire scan is done in one shot. This can get overwhelming
> for
> any library of some size. It can be broken down to allow the scheduler to
> control the scan. This releases some cpu time for other tasks, but also
> takes
> longer to scan. This same method was used for the MusicMagic scanning in
> the
> 6.0 builds.

Any improvements would be much appreciated. Thanks again for you attention

[kdf]

Quoting Adam White <adam (AT) AdamAndLiz (DOT) com>:


> Yes, I would have re-started both after it failed at the 3am re-scan and
> after it went wild when adding tracks to moodlogic.

I'm not following you here. how was the scan failing at 3am?

One thing you can try:
Server settings->performance
click 'wipe cache'
wait however long it takes to finish the scan.
then run moodlogic and do the things you want.

Of course, this then requires that you leave the PC on and slimserver running.
Any time you restart, a change to moodlogic would start the scan process anew,
but it should run its course without failing. Then you'd have the interval
active again.


Going back to your original third issue. I've been unable to see where the
tracks start at zero. I have a viewer that lets me look at the raw moodlogic
db, and the 'track numbers' appear to start at 1. With moodlogic on, you would
extract this info direct from the moodlogic profiling database, whereas with it
off, the server relies on ID3 tags. I would suspect that you've somehow locked
onto an album or set of albums that have somehow been profiled as starting from
track 0.

-kdf

[Adam White]

----- Original Message -----
From: "kdf" <slim-mail (AT) deane-freeman (DOT) com>
To: "Slim Devices Discussion" <discuss (AT) lists (DOT) slimdevices.com>
Sent: Monday, January 03, 2005 8:16 PM
Subject: [slim] Slimserver and Moodlogic not playing
nicelyanfthrowingtheir toys out of the pram


> Quoting Adam White <adam (AT) AdamAndLiz (DOT) com>:
>
>
>> Yes, I would have re-started both after it failed at the 3am re-scan and
>> after it went wild when adding tracks to moodlogic.
>
> I'm not following you here. how was the scan failing at 3am?
>

Taken from my original post, the following lines are logged, then nothing
else. I'm assuming this is the last failure message: (You mentioned this
was a known problem)
2005-01-03 03:08:56.1235 using moodlogic: 1
2005-01-03 03:09:01.1276 using moodlogic: 1
Can't use an undefined value as an ARRAY reference at
/PerlApp/Slim/Utils/Scan.pm line 194.


>
> Going back to your original third issue. I've been unable to see where
> the
> tracks start at zero. I have a viewer that lets me look at the raw
> moodlogic
> db, and the 'track numbers' appear to start at 1. With moodlogic on, you
> would
> extract this info direct from the moodlogic profiling database, whereas
> with it
> off, the server relies on ID3 tags. I would suspect that you've somehow
> locked
> onto an album or set of albums that have somehow been profiled as starting
> from
> track 0.
>
This may well be a moodlogic problem. I'll clear the cachedo a refresh and
see if I can re-create it.

[kdf]

Quoting Adam White <adam (AT) AdamAndLiz (DOT) com>:


> Taken from my original post, the following lines are logged, then nothing
> else. I'm assuming this is the last failure message: (You mentioned this
> was a known problem)
> 2005-01-03 03:08:56.1235 using moodlogic: 1
> 2005-01-03 03:09:01.1276 using moodlogic: 1
> Can't use an undefined value as an ARRAY reference at
> /PerlApp/Slim/Utils/Scan.pm line 194.

ah..that. no idea what exactly is causing that one, and it doesn't happen every
time.


> This may well be a moodlogic problem. I'll clear the cachedo a refresh and
> see if I can re-create it.

The server doesn't alter the data it gets from moodlogic, so if moodlogic has
the track number marked as 0, then it will be 0 in slimserver. However,
moodlogic does allow you to corect file info, which would be imported into
slimserver after a scan. Try looking at other albums to see if they are all
starting at track 0.

-kdf

[kdf]

Quoting Adam White <adam (AT) AdamAndLiz (DOT) com>:


> Taken from my original post, the following lines are logged, then nothing
> else. I'm assuming this is the last failure message: (You mentioned this
> was a known problem)
> 2005-01-03 03:08:56.1235 using moodlogic: 1
> 2005-01-03 03:09:01.1276 using moodlogic: 1
> Can't use an undefined value as an ARRAY reference at
> /PerlApp/Slim/Utils/Scan.pm line 194.

actually, I think this might be related to the current problem with windows
shortcuts in 6.0. If you can, remove windows shortcuts for now, though I'm not
certain those are the direct cause.

however, there is also the spousal factor, which likely means using 5.4.1. 6.0
stuff is still rather experimental. The new features are tempting, but those
new features are also prone to instability. The focus for 6.0 is not so much
on stability for now.

-kdf