Guide failure to update after a few months of flawless performance

[jwk]

EPG123 has worked flawlessly since installation. I believe this morning 3-15-2020 it failed to update. Tracelog attached.

Some things to note:
I had a couple of entries for 4 FiOS channels that were marked for future use as 4K. A few days or maybe a week or so they guide information stated something to effect that they were no longer available or something to that effect. A couple of days ago they were apparently removed from the guide listing:

Code: Select all

[3/13/2020 3:04:57 AM] [ INFO] Removing VZ31 from channel 950 in lineup EPG123 Verizon Fios Montgomery Village - Digital (Montgomery Village).
[3/13/2020 3:04:57 AM] [ INFO] Removing VZ31 from channel 951 in lineup EPG123 Verizon Fios Montgomery Village - Digital (Montgomery Village).
[3/13/2020 3:04:57 AM] [ INFO] Removing VZ31 from channel 952 in lineup EPG123 Verizon Fios Montgomery Village - Digital (Montgomery Village).
[3/13/2020 3:04:57 AM] [ INFO] Removing VZ31 from channel 1005 in lineup EPG123 Verizon Fios Montgomery Village - Digital (Montgomery Village).

There are Error lines in the log on 3-15-2020 at 10-25-58 AM which appear to be from 2 channels that were recording at the time EPG123 was updating... how does EPG123 handle these kinds of errors, does it keep trying to process these channels until they stop recording, or does it fail out after a certain number of tries or length of time (guide updating is normally done at 3am and I haven't run into this before, I reset it to 10:05am today to see if it would update to see if it would update correctly (and it seems that it did) after failing the 3:00am update today.

Code: Select all

[3/15/2020 10:25:58 AM] [ERROR] Unhandled exception caught from epg123Client.exe. message: Access to the path 'Global\{CD7E6857-7D92-4A2F-B3AB-ED8CB42C6F65}' is denied.
[3/15/2020 10:53:46 AM] [ERROR] Unhandled exception caught from epg123Client.exe. message: Access to the path 'Global\{CD7E6857-7D92-4A2F-B3AB-ED8CB42C6F65}' is denied.
[3/15/2020 10:54:01 AM] [ERROR] Unhandled exception caught from epg123Client.exe. message: Access to the path 'Global\{CD7E6857-7D92-4A2F-B3AB-ED8CB42C6F65}' is denied.
[3/15/2020 11:02:55 AM] [ERROR] Unhandled exception caught from epg123Client.exe. message: Access to the path 'Global\{CD7E6857-7D92-4A2F-B3AB-ED8CB42C6F65}' is denied.
[3/15/2020 11:05:44 AM] [ INFO] Recording in progress: 10:30 AM - 11:30 AM on channel 4.1 WRCDT -> Meet the Press - Meet the Press
[3/15/2020 11:05:44 AM] [ INFO] Recording in progress: 10:00 AM - 11:05 AM on channel 569 AXSTV -> KC and the Sunshine Band - Live From The Bomb Factory - 
[3/15/2020 11:11:55 AM] [ERROR] Unhandled exception caught from epg123Client.exe. message: Access to the path 'Global\{CD7E6857-7D92-4A2F-B3AB-ED8CB42C6F65}' is denied.
[3/15/2020 11:31:04 AM] [ERROR] Unhandled exception caught from epg123Client.exe. message: Access to the path 'Global\{CD7E6857-7D92-4A2F-B3AB-ED8CB42C6F65}' is denied.

The update that failed:
I don't know what caused these errors, but this occurred during the 3/15/2020 3:00 AM update that failed:

Code: Select all

[3/15/2020 3:00:10 AM] [ERROR] sdGetLineups() Unknown exception thrown. Message: Object reference not set to an instance of an object.
[3/15/2020 3:00:10 AM] [ERROR] Failed to create MXF file. Exiting.

Everything seems to be back to normal now, but if you could weigh in on what might have caused the listed errors, it would enhance my knowledge of EPG123 a bit further,

Thank you!

[garyan2]

Actually, on 3/14 it failed to update due to not getting a token from Schedules Direct. It should have given a red status logo then but didn't because the MXF file was 23.95 hours old which is less than the 24.00 hours threshold. I'll have to adjust my threshold to catch this scenario and properly update the status logo.

On 3/15, it failed to update because it failed to retrieve your lineups from Schedules Direct. I've been seeing this issue off-and-on for a couple weeks now. Because the MXF file was now 47.97 hours hold, you got the proper status logo.

The errors you see while you were recording are due to you trying to open the client GUI while the it is currently "importing" the MXF file. The client is actually paused until you are done recording at 11:34. If the client is importing, even while paused, it will block another client session from starting and generate those errors. Also of note, those errors were not part of the update process and therefore do not affect the overall status and the status logo will be green/yellow.

Basically, the 2 real failures you had were due to a non-response or invalid response from Schedules Direct... first for your token, and then for retrieving your lineups. Your update at 10:05 worked without any hiccups so it could be related to your choice of a 3:00 AM update time along with a lot of other folks. You may want to change/randomize your time a little to improve your odds of a quick update.

For the latest discussion of the import delay while recording, see viewtopic.php?f=99&t=12879&p=138606#p138604.

[jwk]

Okay, the EPG 123 client won't open when you are recording... wasn't sure about that but it did cross my mind part way through and I stopped trying to open it until the recordings were done.
And the 2 real failures I received were due to SchedulesDirect, not to my installation.

I was surprised how long it took for some of the schedule updates. I haven't got the fastest of processors either, so maybe part of the speed is due to the time it takes to apply the changes, especially when the CPU is busy producing video in WMC. I have a couple of newer mobos w i7-2700K cpus which are about to replace my current DVR mobos.

I'll integrate your update timing advice into my plan asap.

Thank you Gary

[garyan2]

Clarification: EPG123 will open while you are recording... it just won't open if you currently updating your guide and the epg123Client.exe program is already running.

Uninterrupted, uneventful updates only took you 5:03 on 3/13, 3:56 on 3/12, 4:03 on 3/11, 3:23 on 3/09, 3:19 on 3/08... pretty good for 14 days on 117 stations.

[Space]

My first run after a clean EPG123 install took 13 minutes to completely load the guide with ~360 stations. Runs after that also took around 12 to 13 minutes to update the guide.

But now, after a month, each daily update takes in excess of 30 minutes.

I''m not sure why it is now taking more than double the time to complete. I am running it at about the same time of day as I ran it initially.

buildAllProgramEntries() went from taking 6 minutes to taking 12 minutes. importMxfFile() went from taking 3-4 minutes to taking 9 minutes.

I understand that the time can vary by how much data and the type of changes needed, but the MXF file has remained about the same size, and I was just wondering if this is normal or if I should be looking for problems?

[jwk]

Clarification: EPG123 will open while you are recording... it just won't open if you currently updating your guide and the epg123Client.exe program is already running.

Uninterrupted, uneventful updates only took you 5:03 on 3/13, 3:56 on 3/12, 4:03 on 3/11, 3:23 on 3/09, 3:19 on 3/08... pretty good for 14 days on 117 stations.

Clarification understood.

It was my impression that program schedules were released from broadcasters on a weekly basis, one to two weeks in advance (and regularly have slots that either still need to be filled program changes to be made. If this is true, wouldn't those week-at-a-time dumps be larger than the daily corrections and addendums, and therefore some days would have less data and take less time to download and process, and the weeklies have more data and take more time, or isn't that the way it works? If not, what does cause some to take more time than others (other than the actions of some idiots like me?

[adam1991]

Every day's download extends the guide one more day. It's a daily dump of two week data that was added to and also corrected as needed the previous day.

[garyan2]

My first run after a clean EPG123 install took 13 minutes to completely load the guide with ~360 stations. Runs after that also took around 12 to 13 minutes to update the guide.

But now, after a month, each daily update takes in excess of 30 minutes.

I''m not sure why it is now taking more than double the time to complete. I am running it at about the same time of day as I ran it initially.

buildAllProgramEntries() went from taking 6 minutes to taking 12 minutes. importMxfFile() went from taking 3-4 minutes to taking 9 minutes.

I understand that the time can vary by how much data and the type of changes needed, but the MXF file has remained about the same size, and I was just wondering if this is normal or if I should be looking for problems?

There can be many reasons, but I think a big part of the time is just reading the cached files, especially if you have a mechanical drive. The updates are actually faster if you don't have any cached files than when you do. And if you have 60,000+ cached files, it is even more noticeable. For the downloads, I have the log file show how long it took a request to complete and how large the download was. You may be able to see if the response time from Schedules Direct is a contributor.

I may look into using SQL to handle caching the JSON files to make this quicker. I got some learning to do for that.

[Space]

getAllScheduleEntryMd5s() took around 1.5 to 2 minutes in the early downloads, and the latest ones has it at about 3 minutes, so it did increase, but not a large contributor to the increase.

I actually had wanted to ask about the cache. I did notice that it does seem to be somewhat inefficient based on the number of files it has as well as the size of the files (small).

Currently my cache has 62.5K files and I imagine it's not very efficient to have to read them all, but the main thing I noticed is that the total size of all the files is 197MB, but due to them being many small files and the cluster size on the filesystem being 4KB, there is a lot of "slack space" that is being taken up, so the total space used is 336MB, so 70% bigger than it needs to be.

I do think making the reading of the cache more efficient would be a good idea, particularly for those of us with mechanical drives.

But I don't think my issue is only related to the cache, as the MXF import is also taking more than twice as long as it used to, although that time does vary (today's took only 6 minutes).

[garyan2]

The time it takes to import is kinda out of my hands. That is all about loadmxf.exe and WMC to include whatever mcupdate.exe may be doing. I do know that if mcupdate is running at the time, or there is heavy hard drive activity during an import, it can take a very long time to complete.

I just released v1.3.6 which will now contain all the cache files in a single flat file. I also took advantage of this method to remove a lot of non-useful information. Using your example above, your total space used will probably drop down to around 150MB which is even less than the sum of all the cache files originally. In the future, if I decide to compress the file, it would probably get down to 20-25MB... wouldn't that be something.

The downfall, and originally why I didn't take this route initially, is that the cache file will have to be loaded into memory during update. I was running experiments using 15 days and 680 stations and memory usage peaked at around 900MB. For comparison, using v1.3.5.30 it peaked at around 750MB.

[Space]

Nice!

I just ran it and it reduced the cache from 197MB (336MB including slack space) to 146MB and then I ran it again and it took only 6 minutes for a complete run (including the MXF import).

I know that the second time that I ran it it did not actually download any new data (since the initial run that converted the cache had downloaded all the updates), but still. I would assume that building the MXF from the cache is what took the most time, and that is now super fast.

I'll have to see how it goes tomorrow when it actually has new data to download, but I expect to be similarly impressed.

Thanks a lot for this update! I'm sure my poor mechanical hard drive would also thank you if it were sentient.

EDIT: One other thing I forgot to mention... I'm not sure if you have any control over this, but when I installed the new version of EPG123, I had it overwrite the old version and had the option to create desktop icons checked. This caused it to move my existing desktop icons (which I had manually moved to the other side of the screen) to the left side of the screen. I suppose I can just uncheck that option in the future, but maybe the installer can check to see if the icons are already there and not move them somehow?

[garyan2]

Yah, maybe I'll figure that one out before next release. It actually deletes your existing shortcuts and creates new ones... drives me nuts but I haven't been bothered enough to do anything about it.

[Space]

Well, I figured I'd try the first full run after the cache update to see how it goes, and.... the SD_JSON server is down for maintenance...

Hopefully it's not "unscheduled" maintenance.

[Space]

Well, SD is back up, so I ran an update...

Less than 3 minutes.

Are you kidding me?

The MXF import still took 6 minutes, but the EPG123 update took less than 3 minutes. Considering that I was getting over 20 minutes for this with the old cache method I think this change was a very good one.

I'll have to keep an eye on it to see if this persists, but I expect it to continue to be a huge improvement.

Thanks again!

P.S. I'd advise everyone to update to this version to get the increased performance, particularly if you have the cache folder on a mechanical hard drive instead of an SSD.

[adam1991]

As always, update at your own risk.

Does it work for you now? That's always the first and main guiding question.

[Space]

Today's update took 1 minute and 5 seconds to build the MXF file. MFX import was just under 4 minutes. So 5 minutes total vs. ~30 minutes prior to the new version.

I think there might still be issues with SD though due to the data downloaded being smaller than usual and the lastDataUpdate being from 10am this morning (so no update for over 9 hours). I'm not sure how often the SD data is updated, but usually I see updates in the afternoon/evening as well as in the morning.

[garyan2]

They used to pull updates from Gracenote 4 times a day, but I think they reduced that to 2 times a day a year or more ago.

EDIT: Your drive was seriously a limiting factor in your update time. I knew it would be better, but dang!

[garyan2]

Just release v1.3.6.20 with more optimization and a smaller cache file. The only folks that may notice an improvement in performance are those that also create an XMLTV file.

[Space]

Is the cache smaller due to removing unneeded data or compression?

[garyan2]

Unneeded data. It could go even smaller if I didn't support ModernMedia UI+, but as it is, it is pretty good. I went from 160MB to 144MB for 14 days, 640 stations... plus you get some savings by not having the guideImages.xml file anymore.