Vocal synch with faces in xScheduler

JoelDearing commented 5 years ago

To: Keith Fr: Joel Re: Vocal synch in faces.

Hi Keith, We touched on this on the 24th, you said to upgrade to 47. I did. I still get the synch issue in xScheduler.

I tried to attached two :20 video samples but Github wanted something smaller than 10mb. Look for an e-mail from wetransfer.com linked to my AOL address. It contains two zip files that are the videos.

Look for the bad synch in the xScheduler video around the lyric "voices sing and let's be jolly"

Let me know if you need anything else.

Best,

Joel

keithsw1111 commented 5 years ago

can you post the xSchedule logs ... maybe after .48 comes out and you try it one more time. (not because I think it is fixed but because i have removed some noise from the logs)

JoelDearing commented 5 years ago

Sure, when do you expect .48 to come out, and I will look for it.

AzGilrock commented 5 years ago

Isn't it out? I see a checkin so try running xLights.

JoelDearing commented 5 years ago

Dearing 112718 xSchedule_l4cpp.txt

Hope you can use this. The log is just a lot of this: 2018-11-27 21:55:45,129 2020 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 164 2018-11-27 21:55:45,282 2020 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 153 2018-11-27 21:55:45,435 2020 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 153 2018-11-27 21:55:45,588 2020 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 153 2018-11-27 21:55:45,740 2020 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 152 2018-11-27 21:55:45,891 2020 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 151 2018-11-27 21:55:46,048 2020 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 157 2018-11-27 21:55:46,199 2020 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 151

keithsw1111 commented 5 years ago

That is the worst delays I have seen. Something on your machine is massively slowing things down. Everyone I have troubleshot has had either a network issue/conflict or something interfering.

Look for things like:

virus scanners
dropbox etc
anything using lots cpu or network
slow storage

JoelDearing commented 5 years ago

My show computer is a 64 bit, quad core 4 gig of ram, with an SSD I have taken it off the home network to run the Christmas show, I disconnected from wifi, shut down drop box, turned off Avast virus scan, so it should only be doing is the operating system and xScheduler.

Looking in Task Manager, xScheduler is the only application running (and task manager) and looking, in the processes tab it is the biggest user of memory at over 3 gig at this moment, 10:30 AM et while running library music.
I run 7 sequences for show mode, and do not fast start them I also run a library list of ~1200 titles, but again none of those are loaded until needed.
Today task manager showed memory used at over 3 gig, I stopped and closed xScheduler and memory use dropped to 512 MB. Reloaded xScheduler and memory use was at 784 MB. I'll check it later in the day. Could xScheduler have a memory leak?

JoelDearing commented 5 years ago

Two hours later after running just library music from about 11a-1p, now the Task Manager says memory used is at 1.67 gig. I'll update again before the show starts.

AzGilrock commented 5 years ago

Guess we need a disclaimer about using xScheduler to run a pirate radio station...lol.

keithsw1111 commented 5 years ago

Can you attach your xschedule file ... I would like to see if you are doing anything unusual that might explain why i dont see it.

nmiller0113 commented 5 years ago

This is an interesting one. I was considering doing the same thing, so I'm curious what the outcome is on this one.

JoelDearing commented 5 years ago

I'll send it via we transfer.
fyi at 11a task mgr showed 1.67 gig in use all day it just ran the library files show starts at 5:30 5:26p 2.16 gig library music stops 5:29p 2.42 5:30 show starts 5:31 2.43 gig show runs 40 minutes 6:10p 2.48 gig Exited xScheduler drops to 575 mb reload program restart show up to 948 mb 6:19p 1.48 gig

JoelDearing commented 5 years ago

tracking more memory usage 6:30 p 1.00 g 7:30 1.56 g 7:50 playlist stopped at the end and did not loop 7:52 restart this happened the rest of the night. the list would plays, but would not loop. the list is the B list, and it worked OK last week, but that was with ver 2018.36 10:09p 1.23 back to the library log files at the 7:50 stop and 7:52 restart, and log file again at change from show back to library finally 10:16 p 1.72 gig Let me know what else you may need dearing xschedler log 112818 751p.txt dearing xSchedule_l4cpp log wed 112818 107p.txt

keithsw1111 commented 5 years ago

Tell me about your controllers ... are they all e131? Or do you have some serial or lor and if so what are they?

JoelDearing commented 5 years ago

I have a San Devises E682 @ 192.168.1.206 driving < 1000 pixels and a 6804 @ 192.168.1.207 driving > 700 pixels, both on E131. I have two LOR boxes. They are a Gen 3 LOR box that I borrowed (my Gen 2 box is having issues) that feeds the Gen 1 box. I use the LOR dongle on COM3. fyi: After the show I closed out xScheduler, and restarted with the library music, it was just under a gig of memory in task manager, This morning TM was showing 3.42 of memory in use.

keithsw1111 commented 5 years ago

I would like to see results without all your WAV files. I tested last night using MP3s and i dont see any memory leaks. Also see my facebook post re xSchedule pauses ... you may want to run through that list.

JoelDearing commented 5 years ago

OK, I have removed all the .wav files, I'll let you know.
Re: items in your FB post

Reading the FSEQ file from disk
It has always been that way

Make sure nothing else is likely to be accessing the files Dropbox is closed, the e131 are on a static IP
Make sure your virus scanner is not slowing down access ... consider turning it off and testing without it Virus is turned off.
If you have multiple active network connections try disabling the one not used by your show Wireless turned off except when to send you stuff.
If you are internet connected ... try disconnecting to the network No connected
If you are running multicast to wired controllers try making them unicast Running all unicast, been that way for years
If you are using serial devices try disabling those outputs. I need COM3 for LOR. 99% of the blinky flashy works as it should. The only issue is the lip synch of the singing face.

General load

Check memory utilisation Looked at the list xScheduler is using the most at over 2 gig. Note have not restarted since removing the .wav files.

Periodic Processes - 1 minute

If you have more than 2-3 schedules consider disabling most of them. If I disable them, could I re-enable them when needed? I usually schedule the week on Sunday, so the weekend schedules are sitting there for several days before being called on. As you saw in the file I have four M-F playlists and then weekend versions of the M-F playlist. Four into seven days give a good even distribution having each playlist rotate through the week without horizontal rotation issues. Each playlist has an bit in seq1 that is a little different, otherwise they are the same.

keithsw1111 commented 5 years ago

I am not suggesting you make permanent changes ... as you make changes something at some stage is going to fix the problem ... at that point you start to turn things back on until it either slows down again or you have everything working.

Something puzzling in your last response. Are you saying only the singing faces glitch ... everything else is in time? What are these singing faces on? Does it need to receive data over the network? Maybe we are focussing on the wrong thing.

JoelDearing commented 5 years ago

The singing face is on a virtual matrix through an HDMI cable into a projector. No data over the network. Other effects on the virtual matrix are ok. There is one other effect in a different sequence that isn't as snappy as I'd like. That could be my error.

keithsw1111 commented 5 years ago

Did you get my FB Message?

The virtual matrix ... is it FPP or xSchedule? Have you disabled all the universes (or used a null output) for the virtual matrix?

JoelDearing commented 5 years ago

I saw your FB post, and recapped it as to what I am doing in a post further back. Did not see a FB message to me. The virtual matrix is on xSchedule, and in the xLights setup it is a Null output. It does have 20100 channels. Too many? I went for a dense look since it was all virtual. If that is too many what is the max?

keithsw1111 commented 5 years ago

As long as it is null output it shouldnt matter. As at .50 there is extra logging we can turn on but you need to contact me on FB messenger and I will walk you through setting it up

JoelDearing commented 5 years ago

OK, now that I found your message (FB didn't alert me) and now that I know I can make a call via FB do you want to set up a time?

JoelDearing commented 5 years ago

Follow up to the virtual matrix slowing things down on my computer. I noticed that Packet/sec also went way up when I changed the Virt Mtrx from High to bilateral. AT High setting Packet/sec would be 56 / 48, w/ bilateral it jumps to 144 / 152

keithsw1111 commented 5 years ago

That sounds right ... packets/sec should be roughly number of output universes * frames per second ... it will vary slightly but not a lot.

JoelDearing commented 5 years ago

Updated to the new exe and .map you sent me. Here is the log file from just before I stopped it, and after I restarted xScheduler See the screen shot below of Task mgr, on restart it is using more memory that usual

2018-12-02 14:06:18,069 3832 log_base [DEBUG] Asking pinging thread COM3 LOR to stop 2018-12-02 14:06:18,076 3832 log_base [DEBUG] Asking pinging thread 192.168.1.206 E682 to stop 2018-12-02 14:06:18,086 3832 log_base [DEBUG] Asking pinging thread 192.168.1.207 E6804 to stop 2018-12-02 14:06:18,097 3832 log_base [DEBUG] Turning all the lights off. 2018-12-02 14:06:18,131 3832 log_base [DEBUG] Stopping light output. 2018-12-02 14:06:18,131 3832 log_base [DEBUG] Purging commport 2018-12-02 14:06:18,248 3832 log_base [DEBUG] Serial port COM3 closed in 0 milliseconds. 2018-12-02 14:06:18,248 3832 log_base [DEBUG] Virtual matrix stopped VM 031518. 2018-12-02 14:06:18,254 3832 log_base [INFO] Stopped outputting to lights. 2018-12-02 14:06:18,257 3832 log_base [INFO] **** Playlist Library [124868.864] stopping. 2018-12-02 14:06:18,257 3832 log_base [INFO] ######## Playlist step Christmas Eve stopping. 2018-12-02 14:06:18,257 3832 log_base [DEBUG] SDL Audio Stop. 2018-12-02 14:06:18,257 3832 log_base [DEBUG] SDL Audio Stop. 2018-12-02 14:06:18,257 3832 log_base [DEBUG] SDL Audio Removed: id: 52. 2018-12-02 14:06:18,292 3832 log_base [INFO] Closed schedule. 2018-12-02 14:06:18,298 3832 log_base [INFO] xSchedule exiting. 2018-12-02 14:06:18,302 3832 log_base [DEBUG] SDL Audio Stop. 2018-12-02 14:06:18,302 3832 log_base [DEBUG] Pausing audio device 2. 2018-12-02 14:06:18,302 3832 log_base [DEBUG] Result '' 2018-12-02 14:06:18,302 3832 log_base [DEBUG] Closing audio device 2. 2018-12-02 14:06:18,392 3832 log_base [DEBUG] Result '' 2018-12-02 14:06:18,393 3832 log_base [DEBUG] SDL uninitialised 2018-12-02 14:15:01,011 1900 log_base [INFO] *** OnInit: xSchedule started. 2018-12-02 14:15:01,011 1900 log_base [INFO] Version: 2018.50 2018-12-02 14:15:01,011 1900 log_base [INFO] Bits: 64bit 2018-12-02 14:15:01,011 1900 log_base [INFO] Build Date: December 1, 2018 2018-12-02 14:15:01,011 1900 log_base [INFO] Machine configuration: 2018-12-02 14:15:01,011 1900 log_base [INFO] Free Memory: 2035625984. 2018-12-02 14:15:01,011 1900 log_base [INFO] Current directory: C:\Program Files\xLights 2018-12-02 14:15:01,011 1900 log_base [INFO] Machine name: DEARINGLAPTOP4 2018-12-02 14:15:01,011 1900 log_base [INFO] OS: Windows 7 (build 7601, Service Pack 1), 64-bit edition 2018-12-02 14:15:01,011 1900 log_base [INFO] OS: Windows NT family(XP / Vista / 7 / 8 / 10). 6.1 2018-12-02 14:15:01,011 1900 log_base [INFO] 64 bit 2018-12-02 14:15:01,011 1900 log_base [INFO] Little Endian 2018-12-02 14:15:01,096 1900 log_base [DEBUG] Config: AppName 'xSchedule' Path '' Entries 9 Groups 0 Style 2 Vendor ''. 2018-12-02 14:15:01,096 1900 log_base [DEBUG] Read show folder from 'SchedulerLastDir' location C:\Users\Joel\Documents\Show Directory. 2018-12-02 14:15:01,096 1900 log_base [DEBUG] Loading schedule. 2018-12-02 14:15:01,096 1900 log_base [INFO] Loading schedule from C:\Users\Joel\Documents\Show Directory. 2018-12-02 14:15:01,103 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 1-A_Winter_Happy_Land_Let_It_B_Xmas.fseq opened. 2018-12-02 14:15:01,108 1900 log_base [DEBUG] Audio length 479686 overridden by FSEQ length 479650. 2018-12-02 14:15:01,108 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 1-A_Winter_Happy_Land_Let_It_B_Xmas.fseq closed. 2018-12-02 14:15:01,109 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 2_Deck _The_Housetop_O_Wite_Christmas.fseq opened. 2018-12-02 14:15:01,110 1900 log_base [DEBUG] Audio length 233195 overridden by FSEQ length 233150. 2018-12-02 14:15:01,110 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 2_Deck _The_Housetop_O_Wite_Christmas.fseq closed. 2018-12-02 14:15:01,110 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 3_Its_The_Most_Christmas_Eve.fseq opened. 2018-12-02 14:15:01,111 1900 log_base [DEBUG] Audio length 334008 overridden by FSEQ length 334000. 2018-12-02 14:15:01,111 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 3_Its_The_Most_Christmas_Eve.fseq closed. 2018-12-02 14:15:01,111 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 4_JX_LnL_Joy_To_The_World.fseq opened. 2018-12-02 14:15:01,112 1900 log_base [DEBUG] Audio length 278177 overridden by FSEQ length 278150. 2018-12-02 14:15:01,112 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 4_JX_LnL_Joy_To_The_World.fseq closed. 2018-12-02 14:15:01,112 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 5_I_Heard_The_Bells_Rockin_Around.fseq opened. 2018-12-02 14:15:01,113 1900 log_base [DEBUG] Audio length 378720 overridden by FSEQ length 378700. 2018-12-02 14:15:01,113 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 5_I_Heard_The_Bells_Rockin_Around.fseq closed. 2018-12-02 14:15:01,114 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 6_Nutrocker_Twinkle_Twinkle.fseq opened. 2018-12-02 14:15:01,114 1900 log_base [DEBUG] Audio length 279720 overridden by FSEQ length 279700. 2018-12-02 14:15:01,115 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 6_Nutrocker_Twinkle_Twinkle.fseq closed. 2018-12-02 14:15:01,115 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 7_Step_Into_Carol_Of_The_Bells.fseq opened. 2018-12-02 14:15:01,116 1900 log_base [DEBUG] Audio length 412248 overridden by FSEQ length 412200. 2018-12-02 14:15:01,116 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 7_Step_Into_Carol_Of_The_Bells.fseq closed. 2018-12-02 14:15:01,116 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 1-B_Winter_Happy_Land_Let_It_B-Xmas.fseq opened. 2018-12-02 14:15:01,117 1900 log_base [DEBUG] Audio length 487392 overridden by FSEQ length 487350. 2018-12-02 14:15:01,117 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 1-B_Winter_Happy_Land_Let_It_B-Xmas.fseq closed. 2018-12-02 14:15:01,118 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 2_Deck _The_Housetop_O_Wite_Christmas.fseq opened. 2018-12-02 14:15:01,119 1900 log_base [DEBUG] Audio length 233195 overridden by FSEQ length 233150. 2018-12-02 14:15:01,119 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 2_Deck _The_Housetop_O_Wite_Christmas.fseq closed. 2018-12-02 14:15:01,119 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 3_Its_The_Most_Christmas_Eve.fseq opened. 2018-12-02 14:15:01,120 1900 log_base [DEBUG] Audio length 334008 overridden by FSEQ length 334000. 2018-12-02 14:15:01,120 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 3_Its_The_Most_Christmas_Eve.fseq closed. 2018-12-02 14:15:01,120 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 4_JX_LnL_Joy_To_The_World.fseq opened. 2018-12-02 14:15:01,121 1900 log_base [DEBUG] Audio length 278177 overridden by FSEQ length 278150. 2018-12-02 14:15:01,121 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 4_JX_LnL_Joy_To_The_World.fseq closed. 2018-12-02 14:15:01,121 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 5_I_Heard_The_Bells_Rockin_Around.fseq opened. 2018-12-02 14:15:01,122 1900 log_base [DEBUG] Audio length 378720 overridden by FSEQ length 378700. 2018-12-02 14:15:01,122 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 5_I_Heard_The_Bells_Rockin_Around.fseq closed. 2018-12-02 14:15:01,122 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 6_Nutrocker_Twinkle_Twinkle.fseq opened. 2018-12-02 14:15:01,123 1900 log_base [DEBUG] Audio length 279720 overridden by FSEQ length 279700. 2018-12-02 14:15:01,123 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 6_Nutrocker_Twinkle_Twinkle.fseq closed. 2018-12-02 14:15:01,123 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 7_Step_Into_Carol_Of_The_Bells.fseq opened. 2018-12-02 14:15:01,124 1900 log_base [DEBUG] Audio length 412248 overridden by FSEQ length 412200. 2018-12-02 14:15:01,124 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 7_Step_Into_Carol_Of_The_Bells.fseq closed. 2018-12-02 14:15:01,125 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 1-C_Winter_Happy_Land_Let_It_B_Xmas.fseq opened. 2018-12-02 14:15:01,126 1900 log_base [DEBUG] Audio length 487314 overridden by FSEQ length 487300. 2018-12-02 14:15:01,126 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 1-C_Winter_Happy_Land_Let_It_B_Xmas.fseq closed. 2018-12-02 14:15:01,126 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 2_Deck _The_Housetop_O_Wite_Christmas.fseq opened. 2018-12-02 14:15:01,127 1900 log_base [DEBUG] Audio length 233195 overridden by FSEQ length 233150. 2018-12-02 14:15:01,127 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 2_Deck _The_Housetop_O_Wite_Christmas.fseq closed. 2018-12-02 14:15:01,127 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 3_Its_The_Most_Christmas_Eve.fseq opened. 2018-12-02 14:15:01,128 1900 log_base [DEBUG] Audio length 334008 overridden by FSEQ length 334000. 2018-12-02 14:15:01,128 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 3_Its_The_Most_Christmas_Eve.fseq closed. 2018-12-02 14:15:01,128 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 4_JX_LnL_Joy_To_The_World.fseq opened. 2018-12-02 14:15:01,129 1900 log_base [DEBUG] Audio length 278177 overridden by FSEQ length 278150. 2018-12-02 14:15:01,129 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 4_JX_LnL_Joy_To_The_World.fseq closed. 2018-12-02 14:15:01,129 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 5_I_Heard_The_Bells_Rockin_Around.fseq opened. 2018-12-02 14:15:01,130 1900 log_base [DEBUG] Audio length 378720 overridden by FSEQ length 378700. 2018-12-02 14:15:01,130 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 5_I_Heard_The_Bells_Rockin_Around.fseq closed. 2018-12-02 14:15:01,130 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 6_Nutrocker_Twinkle_Twinkle.fseq opened. 2018-12-02 14:15:01,131 1900 log_base [DEBUG] Audio length 279720 overridden by FSEQ length 279700. 2018-12-02 14:15:01,131 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 6_Nutrocker_Twinkle_Twinkle.fseq closed. 2018-12-02 14:15:01,132 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 7_Step_Into_Carol_Of_The_Bells.fseq opened. 2018-12-02 14:15:01,132 1900 log_base [DEBUG] Audio length 412248 overridden by FSEQ length 412200. 2018-12-02 14:15:01,133 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 7_Step_Into_Carol_Of_The_Bells.fseq closed. 2018-12-02 14:15:01,133 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 1-D_Winter_Happy_Land_Let_It_B_Xmas.fseq opened. 2018-12-02 14:15:01,134 1900 log_base [DEBUG] Audio length 496195 overridden by FSEQ length 496150. 2018-12-02 14:15:01,134 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 1-D_Winter_Happy_Land_Let_It_B_Xmas.fseq closed. 2018-12-02 14:15:01,134 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 2_Deck _The_Housetop_O_Wite_Christmas.fseq opened. 2018-12-02 14:15:01,135 1900 log_base [DEBUG] Audio length 233195 overridden by FSEQ length 233150. 2018-12-02 14:15:01,135 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 2_Deck _The_Housetop_O_Wite_Christmas.fseq closed. 2018-12-02 14:15:01,135 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 3_Its_The_Most_Christmas_Eve.fseq opened. 2018-12-02 14:15:01,136 1900 log_base [DEBUG] Audio length 334008 overridden by FSEQ length 334000. 2018-12-02 14:15:01,136 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 3_Its_The_Most_Christmas_Eve.fseq closed. 2018-12-02 14:15:01,136 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 4_JX_LnL_Joy_To_The_World.fseq opened. 2018-12-02 14:15:01,137 1900 log_base [DEBUG] Audio length 278177 overridden by FSEQ length 278150. 2018-12-02 14:15:01,137 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 4_JX_LnL_Joy_To_The_World.fseq closed. 2018-12-02 14:15:01,137 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 5_I_Heard_The_Bells_Rockin_Around.fseq opened. 2018-12-02 14:15:01,138 1900 log_base [DEBUG] Audio length 378720 overridden by FSEQ length 378700. 2018-12-02 14:15:01,138 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 5_I_Heard_The_Bells_Rockin_Around.fseq closed. 2018-12-02 14:15:01,139 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 6_Nutrocker_Twinkle_Twinkle.fseq opened. 2018-12-02 14:15:01,139 1900 log_base [DEBUG] Audio length 279720 overridden by FSEQ length 279700. 2018-12-02 14:15:01,139 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 6_Nutrocker_Twinkle_Twinkle.fseq closed. 2018-12-02 14:15:01,139 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 7_Step_Into_Carol_Of_The_Bells.fseq opened. 2018-12-02 14:15:01,140 1900 log_base [DEBUG] Audio length 412248 overridden by FSEQ length 412200. 2018-12-02 14:15:01,141 1900 log_base [INFO] FSEQ file C:\Users\Joel\Documents\Show Directory\SEC 7_Step_Into_Carol_Of_The_Bells.fseq closed. 2018-12-02 14:15:01,688 1900 log_base [INFO] Loaded outputs from C:\Users\Joel\Documents\Show Directory/xlights_networks.xml. 2018-12-02 14:15:01,688 1900 log_base [INFO] SyncMode: STANDALONE 2018-12-02 14:15:01,688 1900 log_base [INFO] Allocated frame buffer of 24212 bytes 2018-12-02 14:15:01,688 4828 log_base [DEBUG] Pinging thread COM3 LOR started 2018-12-02 14:15:01,688 4100 log_base [DEBUG] Pinging thread 192.168.1.207 E6804 started 2018-12-02 14:15:01,688 4792 log_base [DEBUG] Pinging thread 192.168.1.206 E682 started 2018-12-02 14:15:01,688 1900 log_base [INFO] starting server on 0.0.0.0:80... 2018-12-02 14:15:01,689 1900 log_base [INFO] server running on 0.0.0.0:80 2018-12-02 14:15:01,689 1900 log_base [DEBUG] Adding IPs to ping. 2018-12-02 14:15:01,690 1900 log_base [DEBUG] Update the playlist tree. 2018-12-02 14:15:01,691 1900 log_base [DEBUG] Creating buttons. 2018-12-02 14:15:01,696 1900 log_base [DEBUG] Schedule loaded. 2018-12-02 14:15:02,197 1900 log_base [DEBUG] Checking the schedule ... 2018-12-02 14:15:02,197 1900 log_base [DEBUG] Checking playlist 2018 List A schedule List A Sched. 2018-12-02 14:15:02,197 1900 log_base [DEBUG] Checking playlist 2018 List A schedule List A Sched Weeknd. 2018-12-02 14:15:02,198 1900 log_base [DEBUG] Checking playlist List B schedule List B Sched. 2018-12-02 14:15:02,198 1900 log_base [DEBUG] Checking playlist List B schedule List B Sched Wknd. 2018-12-02 14:15:02,198 1900 log_base [DEBUG] Checking playlist List C schedule List C Sched. 2018-12-02 14:15:02,198 1900 log_base [DEBUG] Checking playlist List C schedule List C Sched Wknd. 2018-12-02 14:15:02,198 1900 log_base [DEBUG] Checking playlist List D schedule List D Sched. 2018-12-02 14:15:02,198 1900 log_base [DEBUG] Checking playlist List D schedule List D Wknd. 2018-12-02 14:15:02,198 1900 log_base [DEBUG] Checking playlist Library schedule Library Weekday. 2018-12-02 14:15:02,198 1900 log_base [DEBUG] It should be active. 2018-12-02 14:15:02,199 1900 log_base [DEBUG] Copying playlist Library [124865.576] steps 413. 2018-12-02 14:15:02,747 1900 log_base [INFO] **** Playlist Library [124865.576] starting to play. 2018-12-02 14:15:02,747 1900 log_base [INFO] **** RANDOM 2018-12-02 14:15:02,747 1900 log_base [INFO] Playlist Library [124865.576] randomly chose step 357 of 413. 2018-12-02 14:15:02,747 1900 log_base [INFO] ######## Playlist step 05 Pat-A-Pan starting. 2018-12-02 14:15:02,747 1900 log_base [DEBUG] Constructing xLightsVamp 2018-12-02 14:15:02,747 1900 log_base [DEBUG] Vamp plugin loader ... created 2018-12-02 14:15:02,747 1900 log_base [DEBUG] Audio Manager Constructor start 2018-12-02 14:15:02,747 1900 log_base [DEBUG] Audio Manager Constructor: Loading media file. 2018-12-02 14:15:03,531 1900 log_base [INFO] Track Size: 12790657, Time Base Den: 44100 => Length 290037ms 2018-12-02 14:15:03,531 1900 log_base [DEBUG] Preparing to load song data. 2018-12-02 14:15:03,531 1900 log_base [DEBUG] SDL Audio Added: id: 0, rate: 44100, len: 51162628, lengthMS: 290037, trackSize: 12790657. 2018-12-02 14:15:03,531 1900 log_base [DEBUG] Audio Manager Constructor: Media file loaded. 2018-12-02 14:15:03,531 4396 log_base [DEBUG] DoLoadAudioData: Doing load of song data. 2018-12-02 14:15:03,531 4396 log_base [DEBUG] formatContext 0x6e436e0 2018-12-02 14:15:03,531 4396 log_base [DEBUG] codecContext 0x6d4ecc0 2018-12-02 14:15:03,531 4396 log_base [DEBUG] audioStream 0x6dc2be0 2018-12-02 14:15:03,531 1900 log_base [DEBUG] Audio Manager Constructor: Skipping preparing frame data as timing not known yet. 2018-12-02 14:15:03,531 4396 log_base [DEBUG] frame 0x6f115c0 2018-12-02 14:15:03,531 1900 log_base [INFO] Audio file loaded. 2018-12-02 14:15:03,531 4396 log_base [DEBUG] DoLoadAudioData: AAA. 2018-12-02 14:15:03,531 4396 log_base [DEBUG] DoLoadAudioData: BBB. 2018-12-02 14:15:03,531 1900 log_base [INFO] Filename: C:\Christmas\05 Pat-A-Pan.mp3 2018-12-02 14:15:03,531 1900 log_base [INFO] Title: Pat-A-Pan 2018-12-02 14:15:03,531 1900 log_base [INFO] Album: Christmas in the Aire 2018-12-02 14:15:03,532 1900 log_base [INFO] Artist: Mannheim Steamroller 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: CCC. 2018-12-02 14:15:03,532 1900 log_base [INFO] Length: 290037ms 2018-12-02 14:15:03,532 1900 log_base [INFO] Channels 2, Bits: 2, Rate 44100 2018-12-02 14:15:03,532 1900 log_base [DEBUG] ID 0 Seeking to 0MS Length 290037MS ... calculated audio_len: 51162524. 2018-12-02 14:15:03,532 1900 log_base [DEBUG] SDL Audio Play. 2018-12-02 14:15:03,532 1900 log_base [DEBUG] SDL Audio Pause: id: 0, pause 0. 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: DDD. 2018-12-02 14:15:03,532 1900 log_base [INFO] Playlist Library suspending. 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: EEE. 0 2018-12-02 14:15:03,532 1900 log_base [INFO] Playlist step 05 Pat-A-Pan suspending. 2018-12-02 14:15:03,532 1900 log_base [DEBUG] SDL Audio Pause: id: 0, pause 1. 2018-12-02 14:15:03,532 1900 log_base [INFO] Scheduler starting suspended playlist Library due to schedule Library Weekday. 2018-12-02 14:15:03,532 1900 log_base [DEBUG] Checking playlist Library schedule Library Weekend. 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: FFF. 0 2018-12-02 14:15:03,532 1900 log_base [INFO] Unsuspending playlist Library due to schedule Library Weekday. 2018-12-02 14:15:03,532 1900 log_base [INFO] Playlist Library unsuspending. 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: GGG. 1152 2018-12-02 14:15:03,532 1900 log_base [INFO] Playlist step 05 Pat-A-Pan unsuspending. 2018-12-02 14:15:03,532 1900 log_base [DEBUG] SDL Audio Pause: id: 0, pause 0. 2018-12-02 14:15:03,532 1900 log_base [DEBUG] SDL Audio Play. 2018-12-02 14:15:03,532 1900 log_base [DEBUG] Active scheduled playlists: 1 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: HHH. 1152 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: EEE. 1152 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: FFF. 1152 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: GGG. 2304 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: HHH. 2304 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: EEE. 2304 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: FFF. 2304 2018-12-02 14:15:03,532 1900 log_base [DEBUG] Playlist Library [124865.824], Schedule Library Weekday Priority 7 Running Step '05 Pat-A-Pan' Time 0:00.000/4:50.037 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: GGG. 3456 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: HHH. 3456 2018-12-02 14:15:03,532 4396 log_base [DEBUG] DoLoadAudioData: EEE. 3456 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: FFF. 3456 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: GGG. 4608 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: HHH. 4608 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: EEE. 4608 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: FFF. 4608 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: GGG. 5760 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: HHH. 5760 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: EEE. 5760 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: FFF. 5760 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: GGG. 6912 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: HHH. 6912 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: EEE. 6912 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: FFF. 6912 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: GGG. 8064 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: HHH. 8064 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: EEE. 8064 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: FFF. 8064 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: GGG. 9216 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: HHH. 9216 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: EEE. 9216 2018-12-02 14:15:03,533 4396 log_base [DEBUG] DoLoadAudioData: FFF. 9216 2018-12-02 14:15:03,561 1900 log_base [DEBUG] Starting light output. 2018-12-02 14:15:03,561 1900 log_base [DEBUG] Opening serial port COM3. Baud rate = 115200. Config = 8N1. 2018-12-02 14:15:03,573 1900 log_base [DEBUG] Serial port COM3 open. 2018-12-02 14:15:03,622 4396 log_base [DEBUG] DoLoadAudioData: Progress 10% 2018-12-02 14:15:03,624 1900 log_base [DEBUG] Virtual matrix started VM 031518. 2018-12-02 14:15:03,649 1900 log_base [INFO] Player window created location (1417, 0) size (1806, 1080). 2018-12-02 14:15:03,650 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 1476 2018-12-02 14:15:03,733 4396 log_base [DEBUG] DoLoadAudioData: Progress 20% 2018-12-02 14:15:03,835 4396 log_base [DEBUG] DoLoadAudioData: Progress 30% 2018-12-02 14:15:03,932 4396 log_base [DEBUG] DoLoadAudioData: Progress 40% 2018-12-02 14:15:04,030 4396 log_base [DEBUG] DoLoadAudioData: Progress 50% 2018-12-02 14:15:04,129 4396 log_base [DEBUG] DoLoadAudioData: Progress 60% 2018-12-02 14:15:04,226 4396 log_base [DEBUG] DoLoadAudioData: Progress 70% 2018-12-02 14:15:04,321 4396 log_base [DEBUG] DoLoadAudioData: Progress 80% 2018-12-02 14:15:04,415 4396 log_base [DEBUG] DoLoadAudioData: Progress 90% 2018-12-02 14:15:04,508 4396 log_base [DEBUG] DoLoadAudioData: Cleaning up 2018-12-02 14:15:04,508 4396 log_base [DEBUG] DoLoadAudioData: Song data loaded in 976. Read: 12790656 2018-12-02 14:15:12,959 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 1091 2018-12-02 14:15:13,408 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 193 2018-12-02 14:15:13,690 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 128 2018-12-02 14:15:14,127 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 298 2018-12-02 14:15:14,948 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 334 2018-12-02 14:15:15,809 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 332 2018-12-02 14:15:16,569 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 282 2018-12-02 14:15:17,225 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 375 2018-12-02 14:15:17,946 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 320 2018-12-02 14:15:18,641 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 382 2018-12-02 14:15:19,271 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 141 2018-12-02 14:15:20,323 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 373 2018-12-02 14:15:21,080 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 282 2018-12-02 14:15:21,734 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 384 2018-12-02 14:15:22,712 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 348 2018-12-02 14:15:23,148 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 167 2018-12-02 14:15:23,700 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 346 2018-12-02 14:15:24,891 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 1001 2018-12-02 14:15:25,379 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 154 2018-12-02 14:15:27,536 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 342 2018-12-02 14:15:28,090 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 377 2018-12-02 14:15:28,826 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 556 2018-12-02 14:15:39,635 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 115 2018-12-02 14:15:40,550 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 915 2018-12-02 14:15:41,156 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 104 2018-12-02 14:15:41,419 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 195 2018-12-02 14:15:41,534 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 115 2018-12-02 14:15:41,875 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 268 2018-12-02 14:15:42,625 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 750 2018-12-02 14:15:47,413 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 258 2018-12-02 14:15:47,522 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 109 2018-12-02 14:15:48,605 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 924 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking the schedule ... 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist 2018 List A schedule List A Sched. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist 2018 List A schedule List A Sched Weeknd. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist List B schedule List B Sched. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist List B schedule List B Sched Wknd. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist List C schedule List C Sched. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist List C schedule List C Sched Wknd. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist List D schedule List D Sched. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist List D schedule List D Wknd. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist Library schedule Library Weekday. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] It should be active. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] It was already in the list. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Checking playlist Library schedule Library Weekend. 2018-12-02 14:16:00,561 1900 log_base [DEBUG] Active scheduled playlists: 1 2018-12-02 14:16:00,562 1900 log_base [DEBUG] Playlist Library [124865.824], Schedule Library Weekday Priority 7 Running Step '05 Pat-A-Pan' Time 0:57.005/4:50.037 2018-12-02 14:16:14,017 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 123 2018-12-02 14:16:14,510 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 493 2018-12-02 14:16:14,961 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 180 2018-12-02 14:16:15,274 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 149 2018-12-02 14:16:15,390 1900 log_base [WARN] Frame interval greater than 200% of what it should have been [50] 116 2018-12-02 14:16:15,410 1900 log_base [DEBUG] Viewing log file C:\Users\Joel\AppData\Roaming/xSchedule_l4cpp.log.

keithsw1111 commented 5 years ago

Lets keep the memory usage and performance issues apart ... they are not likely related unless memory usage exceeds the memory in the machine.

Was the log file when using one of the more efficient quality selections.

JoelDearing commented 5 years ago

If I understand this correctly: <>

That log was generated using the old exe and map and then restated with the new exe and .map. You can see the jump in time here from 14:06 to 14:15

2018-12-02 14:06:18,392 3832 log_base [DEBUG] Result '' 2018-12-02 14:06:18,393 3832 log_base [DEBUG] SDL uninitialised 2018-12-02 14:15:01,011 1900 log_base [INFO] *** OnInit: xSchedule started. 2018-12-02 14:15:01,011 1900 log_base [INFO] Version: 2018.50 2018-12-02 14:15:01,011 1900 log_base [INFO] Bits: 64bit

AzGilrock commented 8 months ago

This is way outdated and unlikely for anything here to be useful for troubleshooting. If this is still an issue then open a new issue ticket and reference this one.

xLightsSequencer / xLights

Vocal synch with faces in xScheduler #1346