[Fixed in v7.1] v7 upgrade problem with Sync

[robert5733]

ALRIGHT, I might have her licked. It appears it was the time/date that was killing it. I checked the NAS storage for time and it was not in arizona time zone (no daylight savings here) and the time was off. I set up an NTP time server on my computer to send out timesync and set the NAS up to sync with it.

Transferred new CMC files and set as admin and ran a test sync. It has been 10 minutes and the progress bar looks to be about a 1/3 of the way through 1837 titles with no errors. It does hang after a number of titles for a minute now, I think you mentioned somewhere that the cache might get filled or something. I can live with this if continues this way. I'm sure the actual write will probably take longer. I will update you with a completion time once I get Errors taken care of. Hopefully I didn't screw my database up too bad from all the backups and restores I have done.

Thanks for your help especially for catching the MM logs for inspection.

[Pauven]

Excellent! Great detective work and troubleshooting, I'm impressed. The possibility of an incorrect date/time crossed my mind, but you beat me to the punch. I'll file this away in my mind to perhaps help other users in the future, thanks!

The occasional hang is most likely a server or drive being spun up, but could also be some mild contention between My Movies regular processes and the heavy API access by CCC.

Let me know how it all works out.

[robert5733]

So the CCC test export completed in 3 hours with no errors. It would complete about 30 titles in like 10 seconds and hang for about a minute. This got progressively slower as it went along, as you can tell from my earlier post. It did the first 600 or so in ten minutes, but 2 hrs 50 min for the other 1200. I started checking the MM logs when it would hang, and compared the time it hung with the log, and every time it hung it was checking\updating the time stamp. I have tried with all my might to get two times(PC and NAS) in sync but just can't seem to get them perfect, and they seem to drift. I have the CCC PC as the NTP time server, and the NAS storage is getting it's time from that NTP.

It seems that every time it checks the time stamp, it lags for a minute repeating the update. It seems to check after login, but not every login. I will investigate the timestamp further when I get a chance. according to my calculations, It would seem that, without the time stamp update lag, it could have completed the test in around 29 minutes.

Questions to ponder. Why does MM have to login so many times to the NAS? Last look it would log in twice for one title. Why does it check for time stamps so often, and why are they not at regular intervals, like EVERY sign in attempt, or new title query? I am thinking it might be a timed interval.

Went back to the start and am completing the CMC_CME updates first and checking it for errors, before proceeding with CMC_CCC. It has completed half of the CME export in about 30 minutes and has not hung once during the export. Well not so quick to judgement. It hung about half way through for about 7 minutes according to the log. It had some shorter hangs before that, but real quick. Same thing as CCC logs.

Right after

2024-01-04 16:28:22 . 13 - Common.AddExternalCredentials - UserName 'guest'
2024-01-04 16:28:22 . 13 - Common.AddExternalCredentials - Domain ''
2024-01-04 16:28:22 . 13 - Common.AddExternalCredentials - Current Windows User 'SYSTEM'
2024-01-04 16:28:22 . 13 - Common.AddExternalCredentials - Guest login. Returning True.

is the timestamp, but not every login, and not every one hangs. Tried to compare times and can't see any rhyme or reason as to the time and hang errors, they are just random. Once I do new export with CCC, I will see if maybe they are the same titles that are experiencing the hang. Do you have any idea what it is checking for timestamp? Short logs with timestamp/update at beginning and time 16:28:32 are in earlier post for "non working nuc5 MM log.txt"

Completed the CME export in 2 hrs 17 minutes, thanks to all the time hangs, with no errors. (Should have been 1 hr for 1837 titles if not for hangs)

[Pauven]

Why does MM have to login so many times to the NAS? Last look it would log in twice for one title.

This is what I mentioned earlier about the Dune data. It's scanning the media folder to determine if it is (going from memory) online or offline, media type, etc., and it passes this data in the XML for Dune type devices.

It does it once when I call the Title Data API tag (which is 99% of the data), and it calls it a 2nd time when I call the Movie Data API tag (which I need for things like the YouTube Trailer ID, data not included as part of the main disc title data).

I believe that most of the slowdown is from NAS access, and that the time related DB queries you are seeing are related, but not the root cause. Though you did discover that a time mismatch causes issues here, so perhaps I'm wrong in my assessment. I think the timestamps are an attempt to make this code more efficient, i.e. don't scan if it was recently scanned or something like that, but I've never seen any benefit.

Here's a My Movies forum discussion on this issue from 3 years ago: https://www.mymovies.dk/forum.aspx?g=posts&t=46462

Also, regarding the differences between CME and CCC, CCC exports a lot more data, and makes extra requests to grab everything needed, so it should take longer. 2:17 for CME and 3:00 for CCC seem about right for a collection of your size.

Comparatively, CCC syncs this same data to CMC in mere seconds. My code is super efficient, just sits around literally for hours waiting on My Movies to respond. Also, I believe the slowness when using MMCM, i.e. selecting a title and waiting for the data to show up, is pretty much identical to the API speed. Essentially, if Binnerup fixed one he might actually improve both!!! But again, I could be wrong, that's just a working theory of mine.

Oh, yeah, almost forgot, I see the exact same performance slowdown you see. The export is fast at first, and gets progressively slower the longer it runs. Probably related to memory management, but that's just a guess.

[robert5733]

I'm digging around behind the scenes to see if I can figure this thing out. I restarted the computer and have no programs running, except the MM tray app. I look at the MM logs and they are doing the timestamp every 12 seconds. That is where my slow down is occuring. I get 12 seconds of export, gets interrupted, then it waits for a break it can get in on and exports more titles until the timestamp, repeating through the entire export.

I checked the settings in MM and tried turning off itunes control, wouldn't turn off cause it couldn't access itunes (not installed) so I installed it. No change. It popped a message that I needed to stop it in services so I did that. Timestamps continued. Unchecked "Enable DLNA", still timestamps, Found I had a folder being monitored so I disabled folder monitoring and removed the folder (old mapped drive to Y, to discuss in a minute) ( my mistake it was c\users\public\videos), still timestamps. Went back to Services and stopped MM General Service and the time stamps stopped. Restarted and stopped the SQL Server and timestamps stopped. Restarted SQL server and they returned.

Of note, I think I have been backing up and restoring databases since the beginning of time (maybe 2001). At that time I started with Drive Y:, then later added X:, then W:. That folder monitoring I mentioned earlier must have been from way back when I only had one drive.

Started looking at the logs to see what I could find. When I stopped the MM General Services I got this in the log.

MM General Service stopped log portion.txt

(1.67 KiB) Downloaded 25 times

It says to receive the update message in the Y: folder which doesn't exist

When I stopped the SQL Server I got this

SQL Server stopped portion of log.txt

(1.06 KiB) Downloaded 27 times

It's saying to executereader in the Y: folder

I think that is where it is trying to update the timestamp and read timestamps but it doesn't exist resulting in repeated attempts every 12 seconds

Update:
All of this might be mute. I took a brand new windows install and loaded a brand new downloaded MM on it and made a new profile. As soon as I logged in with no movies in the database, it immediately started with the timestamp every 12 seconds. Went into settings and disabled everything that could be a remote service and rebooted. No change, it is still doing the query. It is something that MM just does I guess and there is no way around it.

A thought.
Disabling SQL Server stops the update. Is SQL Server needed to do the exports? Can you just stop the service and do the export and turn it back on?

[robert5733]

Beat you to an answer. I made a backup and tried disabling SQL Server and it failed with a bad API Response.

I went ahead with the CCC export to let it run overnight, apparently the timestamps don't affect the CCC export, there have been no hangs yet, about 600 movies in now. Think I will go ahead and see what happens before I go to bed at this speed.

Hope I didn't screw something up. CCC Exported in 33 minutes for 1837 titles. More than acceptable for me to use.

Since CME is only for future use in the event of MM demise, I can deal with the slow process once in a while. Just have to remember to go in and clear the logs for MM now and again. I think there might have been a place to turn them off in settings.

Will do the sync with CMC tomorrow and see how it all went.

[Pauven]

When I stopped the SQL Server I got this ...
It's saying to executereader in the Y: folder

I'm pretty sure that's a reference to the developer's PC's drives. I believe Binnerup has (had?) a team of developers, and they're likely working off of a shared network drive, mapped as Y:, so that path is to the source code on the developer's PC.

The part that caught my attention is that it is the project folder for MMCM v5.1, not 5.4. Either lazy naming practices/code management on their part, or they've messed up and included some 5.1 code in 5.4. Probably just laziness - I'm guilty of this too. Scary the thought is that they might have used the wrong code...

It's not trying to execute anything on your Y drive. It's executing code in Database.vb, and it's referencing where that source code originated on the developer's PC. This is information that helps developers troubleshoot an issue.

As soon as I logged in with no movies in the database, it immediately started with the timestamp every 12 seconds.

Yes, I believe this is the My Movies General Service scanning for changes, and this is just one of the checks that it does. Adding a timestamp to the DB allows it to minimize the effort to perform the next check, as you only have to check for new data that changed after the last timestamp. I do something similar with CME's/CCC's changes only export, but I put the timestamp in the Windows Registry.

Adding the timestamp itself isn't a cause of performance issues - rather it is what the timestamps represent, a full scan for any changes. This statement will have more weight at the end of my post here, just you wait...

Disabling SQL Server stops the update. Is SQL Server needed to do the exports? Can you just stop the service and do the export and turn it back on?

As you've already discovered, no. The regular updates are My Movies working as intended. And exporting data via the API pulls data from the database, so the SQL Server (the database host) has to be running or else the DB isn't reachable.

Additionally, the My Movies General Service (which is doing those 12-second interval scans for changes) is also the API host. So if you turn off the General Service to stop the checks, it also prevents CME/CCC from accessing the API.

Hope I didn't screw something up. CCC Exported in 33 minutes for 1837 titles. More than acceptable for me to use.

That's a great time, much better than I get. Though sometimes performance is better after a fresh boot, and sometimes it is better when data is cached from a previous run. I think you had a ton of memory on this PC, which might have helped on caching. It also might be that your NAS cached the data that MM is scanning for on export, so it provided it faster on repeat attempts.

But don't forget that CME's and CCC's changes only export is really, really good, and runs really, really fast. You should be leveraging that as much as possible.

An occasional full export is helpful, though, as there are some My Movies change detection bugs, so some changes don't get flagged in the API, so CME/CCC don't know to export them. These are pretty rare, though, and not something you encounter daily, and normally only affects data of minor importance to CMC.

I normally do a full CCC export once a month. I only run CME a few times a year, when I plug in my backup array to make an offline copy of everything, and the changes only export is good enough for that. I might do a CME full export once every year or two. So while MM's performance is pretty abysmal, I've worked really hard to make CCC mask that issue so that you almost never notice.

Since CME is only for future use in the event of MM demise, I can deal with the slow process once in a while. Just have to remember to go in and clear the logs for MM now and again. I think there might have been a place to turn them off in settings.

One thing to keep in mind is that My Movies is single-threaded. That's a crazy thing in this day and age! CMC/CME/CCC are all heavily multi-threaded, something I had to learn how to do years ago to make my pinball controller software - physics don't pause to wait on code latency! Once you learn how to do it, it's pretty simple, and I simply can't understand why Binnerup is still pushing a single-threaded app (though I'll certainly vote for single-threaded over zero-threaded, please don't take my My Movies away!).

Because My Movies is single threaded, it can literally only do one thing at a time, and everything else gets put on hold. This is essentially thread blocking, and is one of the main reasons MM is so laggy in general.

This means that not only is CCC and CME impacted by the My Movies General Service doing other tasks (like scanning for changes), they also compete with each other. You do NOT want to run CCC and CME exports at the same time, as that will bring the MM to its knees and everything will grind to a halt (and catch fire).

Just have to remember to go in and clear the logs for MM now and again. I think there might have been a place to turn them off in settings.

If you're not actively troubleshooting MM, definitely turn off the logging as much as possible. Not only do the logs slow processing down, but apparently the logs trigger your antivirus software to re-scan them, over and over, as they are being written, so it further degrades performance. This is a well-publicized issue, Binnerup themselves reference it often in their performance troubleshooting steps.

I've never objectively measured performance deltas with logging on/off, but I can definitely say it feels slower with logging on.

[robert5733]

My bust. I didn't have the NAS turned on. You said something before about v6 reading from the CME files, it definitely wasn't reading from the NAS. Maybe that is why it was so quick.

Guess I will have to think about the v7 upgrade and see what happens there. Didn't want to start there because of the error I had before with bad XML. Wanted to make sure I got it to work first.

It does work as far as I can tell now though.

I have two folders in my C:\, CMC_CCC v6 and CMC_CME v6

So that brings me to the next dilemna. Since CCC got the info from CME instead of the NAS, when I update data in MM, is CCC going to see that update? When updating Meta data or adding a new title, will CCC see the change and get the data from the NAS now? Or do I need to export changes in CME first in order for CCC to see (or have the folder to retrieve from) there was an update ?

Then: If I upgrade to v7, is the earlier updates from CME going to redirect v7 to look in CME instead of the NAS, or correct itself to look in the NAS?

I just received a response from Binnerup. They said to update to v5.41 pre release for the timestamp problem. Then asked was it not the auto update feature? I am going to try the pre release and see what happens.

[robert5733]

Well it appears to be what it is. It will just have to work.

I tried the 5.41 Pre Release and it makes no difference, so will just stick with 5.40 for the time being. I contacted them and gave them info and logs to see if they can tell me anything but it appears to be part of the general service. Some sort of timers checking things like "connection states", "files to delete", "WindowsGetExpiredNotificationNames", "GetDatabaseVersion", "GetDatabaseMigrateVersion", etc.... none of which seem to affect export, until it is done. Then it executes "Common.Database.ExecuteNonQuery" every 12 seconds and that's what operates the single thread freezing everything else out.

There is also "Common.Database.ExecuteReader" that executes every 15 seconds, that could be it or also inhibits the export, which is why it is hard for CCC to get an open door in. Query executes then reader executes 3 seconds later, then query 9 seconds later and so on.

I could be wrong about all this, but that's my best analogy.

I enabled high debugging and attached the log from it. That portion starts at 17:15:11 (about) the relevant part starting at 17:16:25

log.txt

(1.58 MiB) Downloaded 28 times

Here is what I found on my dissection of the last export in CME.

It seems to have started the title export at 16:28:21. It was stopped by the query at 16:28:32. It was not able to get another request until 16:29:14 and got blocked again at 16:29:21. Got back in at 16:30:24, blocked at 16:30:33, in at 16:31:15, blocked 16:31:22, in and completed at 16:32:25

So that was 4 min overall for the title but only 32 seconds inside MM. That's assuming there was no dead time before the queries came through. I seem to remember that they were exporting at about 1 second on CME rolling screen when not hung, but the first one always seemed slow. I only have the first title on this log. Will have to check for another log of full export when I get that computer hooked back up. Without the Queries I think the export could be done in 30 minutes (like CCC from CME files on v6) vice 2 hr 17 min. If only we could disable that query during export and re enable after.

Sorry for all the posts, just wanted to share my analysis

[robert5733]

The export time in the log I mentioned earlier shows CME exporting at 3 seconds per title, after 4 titles there is a time query. It is instantaneous with no lag in progress. Unfortunately, I don't have the same logs for the CCC export to look at. Lost them with the restores. But there was a lag in them I remember. Will get new logs later as I mention below, my future on this.

So here is the dilemna I'm facing now. I added 5 movies in MM. I exported CME, Finished lickity split, maybe 45 seconds tops. Then synced CMC(CME) and it synced in less than a minute. Perfect all is well

Exported CCC and it took like 2 min 40 sec per title. Abysmal. Opened CMC(CCC) and the titles were already there. Perfect.

Difference this time is that the NAS is running. So it got the information from the NAS this time instead of CME which answers one of my earlier questions. Next time I will turn the NAS off and do the export and see if goes back to CME.

Wait a minute, this is too much. Although my timer said 2 min 40 sec on it for one title as it scrolled through the log, the finished log says 3 min 19 sec for the entire 5 title export. So that would be 20 hours to finish. Guess only a real export will tell the truth. I disabled logging in MM so I won't have that log to look at.

If this is the case and you fixed getting the data from CME in v7, then I think I want to stay on v6 unfortunately. I'm sure it has to do with MM but I don't hold hopes of them fixing it. If I had to do a full export, that would take me like 70 hours. I just don't know what is going on here. I know you say three hours, the only way I could verify that would be to do a full export. I like my 33 minute export from CME.

I started a test export and let it run for 35 minutes or so.

The scrolling export shows 12 titles in a half hour so far, so not sure how reliable any of this is. The computer would have to be on till the screen shows export done which might be 70 hours, but the actual export might have been done sooner. And this is all theoretical since it is only a test export. I aborted at 15 titles, and have to wait for the program to respond, it took a couple of minutes.

Disconnected the ethernet to NAS and test export. Scroll is super fast, can't even read the text going by. It Is getting it from CME.

I know I got a lot of shit going on here but I have to take a hiatus from this for a couple days to take care of some other stuff, so I will give you a break from me. I am running CMC_CME and CMC_CCC on the CMC v6 beta .006 and CME and CCC on the final v6 .1103. I wonder if running the CME and CCC .006 beta would make a difference. When I experiment next, I am going to take an old computer, run my second account with MM and try the beta CME and CCC along with the beta CMC files, although CMC does not appear to be my problem. I will only test so nothing gets sent to the NAS, don't want to screw that up. Then I will try v7 and see what that does. Last time I tried v7, I had the bug with bad XML files.

If you run a test export, does yours scroll any different than an actual export?

The computer time turns out to possibly not be a possibilty, the old computer is an hour off from the NAS. I think maybe it was just reading the files from CME and not the NAS.

You should have some time to ponder all I have put forth, and take your time getting back to me on all this. I will let you know when I get back to the table. I guess I am just documenting all this while I work work it all out in my brain. I WILL come out with a solution, just need to bear with me...lol...