Girder - CPU Usage High

[harleydude]

A couple of days ago I noticed a couple of odd things, speech broken up and delayed events. When I looked into it G was running at 98% CPU utilization. I shutdown/restarted and everything was fine. About 30 minutes later, the same thing happened.

This weekend I started working on the cause of the problem by looking through the log files and removing all plug-ins and loading back in one at a time. Nothing seems to make sense. With all plug-ins removed G ran fine for 3 hours. Add in a couple of plug-ins, restart and G goes to 100% almost right away. Remove the plug-ins just added and restart, back to 100%.

When I shutdown G when the CPU utilization is high, there is always the "Waiting for lua threads to exit" dialog box displaying. Is there away to find out which lua thread is hosing up the works? I ran DebugView during one shutdown of G and it just confirmed that it was waiting on threads to close before shutting down.

What else can I look for?

[harleydude]

This is frustrating. Any suggestions!!!

[Ron]

Does Girder ever go to 100% without any plugins?

[harleydude]

I just looked this morning, only plug-ins running are AmbeintLight and
SunriseSet and it is at 100%. I am not able to disable these plug-ins.

[Rob H]

Any errors in the Lua console when you try to disable those plugins?

[harleydude]

No errors on disabling the SunRiseSet plug-in. Get the following when trying to disable the AmbientLight plug-in.


TreeScript (golua): ...omixis\Girder5\luascript\components\AmbientLigh t.lua:102: attempt to index local `Instance' (a nil value)
stack traceback:
...omixis\Girder5\luascript\components\AmbientLigh t.lua:102: in function `GetDUIEventsForInstance'
...\luascript\Components/Classes/InstancesContainer.lua:266: in function `RemoveDUIEventsForInstance'
...\luascript\Components/Classes/InstancesContainer.lua:243: in function `StopInstance'
...\luascript\Components/Classes/InstancesContainer.lua:108: in function `Disable'
...iles\Promixis\Girder5\luascript\ComponentManage r.lua:422: in function `DisableComponent'
...\Girder5\/plugins/treescript/ComponentManager UI.lua:186: in function <...\Girder5\/plugins/treescript/ComponentManager UI.lua:159>

[Rob H]

Do you have a file luascript\Components\Classes\InstancesContainer.lu a?

[harleydude]

Yes it is there.

[Rob H]

Okay, replace it with the attached one - make a backup first.

Then try disabling AmbientLight again.

[harleydude]

Done. Now the AmbienLight plug-in can be disabled without and errors.

[Rob H]

Great. And can you now disable SunriseSunset?

[harleydude]

Yes, all components are now disabled. Will let Girder run for a while to see what happens.

[harleydude]

Just checked Girder and it now back to 100% CPU. All components are disabled. What next?

[Ron]

I would like to rule out the Girder core first.

Move all .dll from the Girder plugins directory to a different directory. Not much should work at that point and you might even get some lua errors. But it should not go to 100% CPU usage.

[hoox]

Rick,

If you still have problems, make sure that the checkboxes in the Location Editor are not checked (Auto update and IP monitoring), I think that it uses Lua threads.

And of course disable or move all your custom scripts...

[harleydude]

Ron,

Moved all .dll files to another folder, Girder ran fine for about 3 hours. Moved in 0transport.dll and comserv.dll. After some period of time Girder went back to 100%. I have now removed those again and will let it run over night.

[harleydude]

Well checked Girder this morning, it was running 100% CPU. :( I also checked my development PC and Girder was running > 85% there as well.

[Rob H]

And this is without 0transport.dll and comsrv.dll?

I take it that there are no plugins displayed in the Plugins part of File|Settings? How about File|Component Manager?

Do you have any GMLs loaded?

[harleydude]

No components visible, no plug-ins visible and no GML files loaded.

[hoox]

Maybe the configuration files should also be removed from your Config directory.

[Rob H]

That's possibly a good idea.

Also worth looking for any files in luascript\startup.

Apart from that I'll have to leave this to Ron I think.

[NeoMorph]

In the past I've also had occasions with girder running with 100% cpu right back to 3.3. I found the only way to fix it was to do an uninstall/reinstall and even using the exact same gml and setup it works fine. Currently my G5 install is running between 0% and 1% and that is using a larger gml than the one that generated the 100% state.

I think something gets corrupted and the reinstall fixes it. But as this problem needs to be chased down maybe Ron should have a chance of finding the problem some way.

I know there is a new version of G5 coming out shortly with the debugger... maybe that will help track down the problem.

[Ron]

Hmm that is not good. Let's do 2 things.

1. Keep all plugins out of the \plugins directory. No dlls should be there.
2. Rename the luascript directory to luascript2

Then restart Girder, now we are running without 99% of Lua code and no plugins.

[harleydude]

Thanks Ron.

Done as of right now.

[Ron]

double post. Sorry.

Waiting for results from your trial.

[harleydude]

6.5 hrs, so far do good. What next?

[Ron]

6.5 hours is this longer then the previous times when it went to 100%? If so then put back the luascript directory, do NOT put the plugins back, and remove test.lua from luascript/startup

The only thing that does is start some weather retrieval...

When Girder is at 100% can you still open the about box?

[harleydude]

During these times, Girder is still responsive but sluggish. I have been able to bring up the Component Manager and Settings screens but have not tried the About box.

[Rob H]

Well, I would suggest creating a new luascript directory and putting back a selection of the scripts from the luascript2 directory - some of them will be 'require'd by others so you may have to play around a bit.

I'd suggest starting with at least the following :-

compat-5.1, Additions, pickle, NetRemote, ptable, girconfig, girunits, girsystemevents, Girder2Girder

If it's still okay then add in the classes folder.

Still okay? Add the rest of the files in the luascript folder itself except DeviceManager.lua and ComponentManager.lua

If still okay then try DeviceManager.lua and the DeviceManager folder

By which time it will probably be this time tomorrow!

[Rob H]

Or you could do as Ron suggests first, and if it breaks then follow my suggestion. :)

[harleydude]

How is the precompiled weather script different from CustomWeather? Is it really necessary?

[Ron]

I am not sure why there are 2 weather object. This was a decision by Mike. The precomiled version might be in use by some NR scripts.

[harleydude]

I was not aware that that was in the test.lua file, never really looked, but wondered why I still saw weather events in the logger even though CustomWeather was disabled.

Anyways, so far so good with your method. I will let is run over night and see what happens. If no problems, I will put test.lua back in and see if it causes the problem.

Thanks for your help with this.

[harleydude]

Well it ran fine all night last night. I just added the test.lua file back to the startup folder to see if it pegs again.

[harleydude]

Well that did not take long. With the test.lua script installed the system CPU pegged back to 100%. I guess maybe the precompiled weather script is the culprit?

[harleydude]

Just an FYI.

With all the plug-ins removed from the plug-ins folder I receive the following error message in the LUA console upon Girder startup.


Timer (pcall): ...romixis\Girder5\luascript\Classes/Transport/Core.lua:512: attempt to call field `New' (a nil value)
stack traceback:
...romixis\Girder5\luascript\Classes/Transport/Core.lua:512: in function `CreateTransport'
...romixis\Girder5\luascript\Classes/Transport/Core.lua:430: in function `Initialize'
...romixis\Girder5\luascript\Classes/Transport/Core.lua:368: in function `New'
...romixis\Girder5\luascript\Classes/Transport/Base.lua:106: in function `Initialize'
...romixis\Girder5\luascript\Classes/Transport/Base.lua:77: in function `New'
... Files\Promixis\Girder5\luascript\Classes/Logger.lua:219: in function `handler'
...er5\luascript\Classes/DelayedExecutionDispatcher.lua:47: in function <...er5\luascript\Classes/DelayedExecutionDispatcher.lua:41>
Timer (pcall): ...is\Girder5\luascript\components\TransportManage r.lua:172: attempt to index field `support' (a nil value)
stack traceback:
...is\Girder5\luascript\components\TransportManage r.lua:172: in function `EnumerateSerialPorts'
...is\Girder5\luascript\components\TransportManage r.lua:114: in function `handler'
...er5\luascript\Classes/DelayedExecutionDispatcher.lua:47: in function <...er5\luascript\Classes/DelayedExecutionDispatcher.lua:41>

[Rob H]

Interesting, I'll take a look to see if I can find what might be causing that

The second error probably isn't surprising.

[Ron]

We can't find anything obvious at the moment, but I think that file is no longer used. Simply keep the test.lua file that you have now without the weather load.

Let's put the plugins back and see if we run okay. If that runs okay then enable the customweather component and see if the problem comes back.

[harleydude]

Ron,

I got a bit over zealous and just dumped everything back into the plug-ins folder, activated all the needed plug-ins and components. It has been running for almost 4 hours without any issues. If I do experience any further problems I will resort to a more methodical approach to determining the cause.

As mentioned in an earlier post, I am having the same issue on my development PC, so if you need any further testing done I can use it for testing.

Thanks for the assistance.

[Ron]

You are welcome. I will investigate further here to find out what is wrong with the Weather retrieval code.

[harleydude]

Well hold the presses. I just looked at it again and it is at 100% again. :( Thought for sure that was it. Beginning methodical approach now.

[Ron]

Darn that's too bad.

[harleydude]

Update:

Instead of removing all components/plug-ins, I just disabled the CustomWeather component. Been running for 5+ hours right now.

[Ron]

Let's hope that is the culprit.

[harleydude]

I will do more testing on my development PC as well. I have a copy also installed at work for development and the problem is not present there.

[Rob H]

What other components do you still have enabled? (in case there's an interaction between custom weather and another component).

Are there NetRemote clients running on the network?

How many locations is custom weather updating? And what are they?

[harleydude]

Rob,

I enabled the CustomWeather component long enough to check the configuration. I am collecting weather for 2 cities, Garland, Texas and Mercedes, Texas. When I disabled the CustomWeather component the following showed up in the logger. Shortly after doing this the system went to 100% CPU again.


Time Date Source Details Payloads
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed
07:52:37:140 9/27/2007 NetRemote Error running Lua code Connection Closed


Here is the list of components installed on my system and the status of each.


ConfigFiles - Enabled
Active RFID Receiver - Disabled
Active RFID Tags - Disabled
AmbientLight - Enabled
Caller ID Handler - Enabled
CallerIDModem - Disabled
Custom Weather - Disabled
Elk M1/EZ8 - Enabled
EMail Manager - Enabled
EventCounter - Enabled
Geographical Location - Enabled
GIPLuaEventServer - Disabled
GirderBackup - Enabled
GlobalCache - Disabled
JRMC - Disabled
Logging - Enabled
MediaBridge - Disabled
NetCallerID - Enabled
OmniStat - Disabled
Palm Pad Manager - Enabled
RFXCOM RF Receiver - Disabled
RFXCOM Transmitters - Disabled
RSS - Disabled
SunClock - Disabled
SunriseSunset - Enabled
Transport Manager - Enabled
TTSRandomizer - Enabled
UnitSystem - Enabled
USBUIRT - Enabled
Visonic Transmitters - Disabled
Voice Manager - Enabled
W800RF32 - Enabled
WMI - Disabled
X10 RF Transmitters - Enabled
xAPManager - Enabled
xAPPing - Enabled
xAPSpeedfan - Enabled
xAPZoneMinder - Enabled
ZoomPlayer - Disabled
ZWave - Disabled


I do not have any NR clients running on a full time basis. I did connect a client last night while doing some testing.

[kanebullen]

Hi,

Thought I'd piggy-back this thread instead of starting a new one.

I've been playing with the Russound RNET plugin. I didn't have it working very well under G4 (I could send commands, but couldn't receive anything), so considering I'm just doing my "proof of concept" at the moment, I figured I may as well try out G5..

The Russound plugin seems to work well (I can see the keypad events in the Log etc).. But, as soon as I assign a comport to the Russound Plugin, Girder goes up to 98% CPU usage and sits there.

If I change the serial port to "unassigned", it goes down to pretty much nothing, but as soon as I reassign again, it's straight back up to 98% or so.

Any suggestions on what I can try?

Cheers,

Kane

[Rob H]

As I recall, the RussSound plugin spends quite a while initialising as it has to ask the RussSound about its configuration. How long did it stay at 98%? Or rather, how long did you leave it before unassigning the serial port?

[Rob H]

Rob,

I enabled the CustomWeather component long enough to check the configuration. I am collecting weather for 2 cities, Garland, Texas and Mercedes, Texas. When I disabled the CustomWeather component the following showed up in the logger. Shortly after doing this the system went to 100% CPU again.

It went to 100% after you'd disabled CustomWeather?

[harleydude]

Not sure exactly when it happened, but I only had it enabled for about 1 min. Let me try it again.

[kanebullen]

As I recall, the RussSound plugin spends quite a while initialising as it has to ask the RussSound about its configuration. How long did it stay at 98%? Or rather, how long did you leave it before unassigning the serial port?

How long are we talking for Russound to initialise? I am definately a bit impatient, but have at least left it running for 10-15 minutes. Should I be leaving it for hours to do this?

Is this a once-off initialisation, or every time that girder loads?

Cheers

Kane

[harleydude]

Rob,

I enabled/disabled CustomWeather, it did not go to 100% this time nor did I get the NetRemote errors in the logger. So I loaded up a NR client on another PC, let it run for a moment then shut it down. Then I enabled/disabled CustomWeather, still it did not go to 100%, but the NetRemote errors were present. Below is the logger output, nothing in the LUA console.

[code]Time Date Source Details Payloads
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:09:328 9/27/2007 NetRemote Error running Lua code Connection Closed
08:57:00:093 9/27/2007 WAN IP Address Lua Success (Nothing Triggered)My Girder.gml:\Internet\WAN IP Address
08:57:00:078 9/27/2007 Scheduler WAN IP Check
08:56:44:312 9/27/2007 DUI Subsystem Could not load requested image: D:\Program Files\Promixis\Girder5\CWIcons\Large\.gif
08:56:29:312 9/27/2007 NetRemote Exiting feedback thread for NCC-1701E
08:56:29:296 9/27/2007 NetRemote Closing client for NCC-1701E
08:56:29:296 9/27/2007 NetRemote Unregistering NetRemote client 192.168.1.3:4981
08:56:29:281 9/27/2007 NetRemote Connection closing 192.168.1.3:4981
08:56:29:265 9/27/2007 Communication Server Close Connection 192.168.1.3 4981
08:56:29:265 9/27/2007 Communication Server Close Connection
08:55:58:421 9/27/2007 Communication Server DM.DeviceUpdateDone 812 192.168.1.3 1
08:55:57:750 9/27/2007 Communication Server DM.DeviceUpdateDone 812 192.168.1.3 0
08:55:57:343 9/27/2007 Communication Server DM.Query 812 192.168.1.3 DM.Query
08:55:56:843 9/27/2007 NetRemote Synchronising client NCC-1701E {8deec573-8755-45e6-967c-bc1fd7d20c53}
08:55:56:843 9/27/2007 NetRemote Connected
08:55:55:421 9/27/2007 NetRemote Starting feedback thread for 192.168.1.3
08:55:55:328 9/27/2007 NetRemote Registering NR client
08:55:55:312 9/27/2007 NetRemote Adding client 192.168.1.3
08:55:55:312 9/27/2007 NetRemote Connection from 192.168.1.3:4981
08:55:55:296 9/27/2007 Communication Server New Client Connection 192.168.1.3 4981
[\code]

[Rob H]

10-15 minutes should be plenty long enough I think - unfortunately I don't have a RussSound here, but I do remember Mike saying that it takes a while.

I've had a look at the code and it looks to me as though you might get quite high CPU usage if you get lots of events coming from the RussSound. How fast is the PC that's running Girder?

[Rob H]

I think I know where those error messages are coming from - it's probably from the DeviceManager trying to update the NR clients. I wouldn't worry about them, although the DM should probably take note of the first error and remove that client from its list.

[harleydude]

Rob/Ron,

I put some debug code into the CustomWeather class file and it appears to be going to 100% during download on the Animated Radar file. Below is the LUA console output.


CW:UpdateCheckAsync():Starting Local
CW:UpdateCheckAsync():ForecastConditions
CW:UpdateCheckAsync():DetailedForecastConditions
CW:UpdateCheckAsync():CurrentConditions
CW:UpdateCC():Begin
CW:UpdateCheckAsync():SatelliteMap
CW:UpdateCheckAsync():AnimatedSatelliteMap
CW:UpdateSatMapAnim():AnimatedSatelliteMap http://xml.customweather.com/xml?client=proximis_test&client_password=xxxx&product=maps&map_product=satellite&name=Garland,United States&anim=true&girder=12 C:\DOCUME~1\RickJr\LOCALS~1\Temp\\CW SAT ANIMATED 1.GIF
If I paste the URL into a browser, I am able to view the image. If I try to view the image in the Temp folder, the image appears to be corrupted.

Hope that helps.

[Ron]

Interesting... have you tried commenting that out? See if you still get the hang?

[Rob H]

Does it actually return from the call to win.URLDownloadToFile?

[harleydude]

Rob,

Will do more testing.

[harleydude]

Here is the latest debug.


CW:UpdateCheckAsync():Starting Local
CW:UpdateCheckAsync():ForecastConditions
CW:UpdateCheckAsync():DetailedForecastConditions
CW:UpdateCheckAsync():CurrentConditions
CW:UpdateCC():Begin
CW:UpdateCheckAsync():SatelliteMap
CW:UpdateSatMap():URL http://xml.customweather.com/xml?client=proximis_test&client_password=xxxxx&product=maps&map_product=satellite&name=Garland,United States&anim=false&girder=10 C:\DOCUME~1\RickJr\LOCALS~1\Temp\\CW SAT 1.JPG
CW:UpdateSatMap():Return from win.URLDownloadToFile
CW:UpdateCheckAsync():AnimatedSatelliteMap
CW:UpdateSatMapAnim():URL http://xml.customweather.com/xml?client=proximis_test&client_password=xxxx&product=maps&map_product=satellite&name=Garland,United States&anim=true&girder=10 C:\DOCUME~1\RickJr\LOCALS~1\Temp\\CW SAT ANIMATED 1.GIF
It appears that when it has problems it does not return from win.URLDownloadToFile.

[kanebullen]

10-15 minutes should be plenty long enough I think - unfortunately I don't have a RussSound here, but I do remember Mike saying that it takes a while.

I've had a look at the code and it looks to me as though you might get quite high CPU usage if you get lots of events coming from the RussSound. How fast is the PC that's running Girder?

It's a laptop from a couple years ago, so not the fastest thing around - a centrino 1.7ghz. But I would have thought that would be okay?

seeing that 10-15 minutes is probably enough - I left it for about an hour last night, and it didn't change.

There are actually very few events coming in from the Russound unit (it's not a production system yet, so I've only got one keypad hooked up). And to test it out, I actually turned the russound unit off, and left it overnight - and it's still at close to 100% CPU this morning.

anything else I can try?

Cheers

Kane

[Ron]

turn off CustomWeather and remove the line

"gir.LoadPreCompiledScript(gir.Scripts.WEATHER)"

from luascript/startup/test.lua

report back... (basically the same as for harleydude

[kanebullen]

turn off CustomWeather and remove the line

"gir.LoadPreCompiledScript(gir.Scripts.WEATHER)"

from luascript/startup/test.lua

report back... (basically the same as for harleydude

Hi

I had actually already done this, to disable the popup weather windows.. (and also tried re-enabling it at one point to see if that helped!)

Cheers

Kane

[Ron]

@harleydude please try the attached lwinfunc library and have debugview open and loggin it's output. There is a loop in that function but I am not sure why it get's stuck. Maybe the debug output will shed some light on that.

http://www.microsoft.com/technet/sysinternals/utilities/debugview.mspx

[harleydude]

Ron,

You mention lwinfunc.dll, but the zip file contains Auxillary.dll. Is this right?

[Ron]

You are right. Been staring at the monitor to long. Here is the correct file.

[harleydude]

Ok here is the DebugView and LUA console logs.

DebugView

[256] %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s
[256] %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s
[256] FastMM has been installed.
[256] %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s
[256] %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s
[256] Sharing an existing instance of FastMM.
[256] Loading D:\Program Files\Promixis\Girder5\auxillary.dll at Base Address 0x01C00000
[256] Sharing an existing instance of FastMM.
[256] Sharing an existing instance of FastMM.
[256] Loading D:\Program Files\Promixis\Girder5\comserverlib.dll at Base Address 0x7E920000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\0transport.dll at Base Address 0x01D90000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\AudioMixer.dll at Base Address 0x7E1B0000
[256] Loading D:\Program Files\Promixis\Girder5\comserverlib.dll at Base Address 0x7E920000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\ComSvr.dll at Base Address 0x7E880000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\copydata.dll at Base Address 0x7E280000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\devnotify.dll at Base Address 0x7E290000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\gip2.dll at Base Address 0x7E8E0000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\httpd.dll at Base Address 0x041E0000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\keyboard.dll at Base Address 0x7E3A0000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\MouseControl.dll at Base Address 0x7E3C0000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\multimon.dll at Base Address 0x7E3E0000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\Scheduler.dll at Base Address 0x04460000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\Sendmessage.dll at Base Address 0x03200000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\serial.dll at Base Address 0x048A0000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\taskcreate.dll at Base Address 0x7E4C0000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\taskswitch.dll at Base Address 0x7E4D0000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\treescript.dll at Base Address 0x7E500000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\WinCon.dll at Base Address 0x7E530000
[256] Loading D:\Program Files\Promixis\Girder5\plugins\ZipExt.dll at Base Address 0x7E550000
--GetMcast: 301a8c0 8417a830
[256] Entering lua_URLDownloadToMemory
[256] Looping lua_URLDownloadToMemory bytes read: 1
[256] Looping lua_URLDownloadToMemory bytes read: 4494
[256] Looping lua_URLDownloadToMemory bytes read: 4494
[256] Looping lua_URLDownloadToMemory bytes read: 0
[256] Done Looping lua_URLDownloadToMemory
[256] EXITING lua_URLDownloadToMemory at exit
[256] EXITING lua_URLDownloadToMemory DONE
[256] Entering lua_URLDownloadToMemory
[256] Looping lua_URLDownloadToMemory bytes read: 1
[256] Looping lua_URLDownloadToMemory bytes read: 4698
[256] Looping lua_URLDownloadToMemory bytes read: 4698
[256] Looping lua_URLDownloadToMemory bytes read: 0
[256] Done Looping lua_URLDownloadToMemory
[256] EXITING lua_URLDownloadToMemory at exit
[256] EXITING lua_URLDownloadToMemory DONE
[256] Entering lua_URLDownloadToMemory
[256] Looping lua_URLDownloadToMemory bytes read: 1
[256] Looping lua_URLDownloadToMemory bytes read: 5232
[256] Looping lua_URLDownloadToMemory bytes read: 5232
[256] Looping lua_URLDownloadToMemory bytes read: 0
[256] Done Looping lua_URLDownloadToMemory
[256] EXITING lua_URLDownloadToMemory at exit
[256] EXITING lua_URLDownloadToMemory DONE
LUA Console

x10-work
xAPSpeedfan_UI:Initialize()
Welcome to Promixis Girder 5.0.0 build 521
Initializing Amps
Initializing LCARS Startup Routines
CW:UpdateCheckAsync():Starting Local
CW:UpdateCheckAsync():ForecastConditions
CW:UpdateCheckAsync():DetailedForecastConditions
CW:UpdateCheckAsync():CurrentConditions
CW:UpdateCC():Begin
CW:UpdateCheckAsync():SatelliteMap
CW:UpdateSatMap():URL http://xml.customweather.com/xml?client=proximis_test&client_password=xxxxx&product=maps&map_product=satellite&name=Garland,United States&anim=false&girder=5 C:\DOCUME~1\RickJr\LOCALS~1\Temp\\CW SAT 1.JPG
CW:UpdateSatMap():Return from win.URLDownloadToFile
CW:UpdateCheckAsync():AnimatedSatelliteMap
CW:UpdateSatMapAnim():URL http://xml.customweather.com/xml?client=proximis_test&client_password=xxxxx&product=maps&map_product=satellite&name=Garland,United States&anim=true&girder=5 C:\DOCUME~1\RickJr\LOCALS~1\Temp\\CW SAT ANIMATED 1.GIF
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running

[Ron]

Rick, can you show me the part of the lua file where you print

'Return from win.URLDownloadToFile'

And did that really lock up right away?

[harleydude]

Here is the lua code.


UpdateSatMapAnim = function (self)
print ('CW:UpdateSatMapAnim():URL',self.SatMapAnim.URL .. '&girder='..math.round(win.GetElapsedSeconds (),0) , self.SatMapAnim.Filename)
local res,err = win.URLDownloadToFile ( self.SatMapAnim.URL .. '&girder='..math.round(win.GetElapsedSeconds (),0) , self.SatMapAnim.Filename )
print ('CW:UpdateSatMapAnim():Return from win.URLDownloadToFile')
if res then -- no error
self.SatMapAnim.LastUpdate = win.GetElapsedSeconds ()
self:Event (Events.Update,ProductIDs.AnimatedSatelliteMap)
else
self:Event (Events.Error,ProductIDs.AnimatedSatelliteMap,"Error "..(err or "unknown"))
end
end,


And yes, it locked right away. It will sometimes do that.

[Ron]

Hmm can you do the same exercise with the attached dll?

1. Run debugview
2. Start Girder
3. get the hang to happen

send lua console and debugview.

Thanks!!

[harleydude]

Ron,

Not much here.

LUA Console Girder Time 21:53:18

CW:UpdateCheckAsync():Starting Local
CW:UpdateCheckAsync():ForecastConditions
CW:UpdateCheckAsync():DetailedForecastConditions
CW:UpdateCheckAsync():CurrentConditions
CW:UpdateCheckAsync():SatelliteMap
CW:UpdateCheckAsync():AnimatedSatelliteMap
CW:UpdateSatMapAnim():URL http://xml.customweather.com/xml?client=proximis_test&client_password=t3mp&product=maps&map_product=satellite&name=Garland,United States&anim=true&girder=5467 C:\DOCUME~1\RickJr\LOCALS~1\Temp\\CW SAT ANIMATED 1.GIF
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running


DebugView

21:53:09
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1440 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1441 bytes
[1136] lua_URLDownloadToFile Looping Read 994 bytes
[1136] lua_URLDownloadToFile Looping Read 0 bytes
[1136] lua_URLDownloadToFile Looping Read 0 bytes

21:53:19
[1136] lua_URLDownloadToFile Looping Read 8192 bytes
[1136] lua_URLDownloadToFile Looping Read 8184 bytes
[1136] lua_URLDownloadToFile Looping Read 8184 bytes
[1136] lua_URLDownloadToFile Looping Read 8184 bytes
[1136] lua_URLDownloadToFile Looping Read 8184 bytes
[1136] lua_URLDownloadToFile Looping Read 8184 bytes
[1136] lua_URLDownloadToFile Looping Read 8184 bytes
[1136] lua_URLDownloadToFile Looping Read 8184 bytes
[1136] lua_URLDownloadToFile Looping Read 882 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes
[1136] lua_URLDownloadToFile Looping Read 1448 bytes

22:03:22
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] Running: 4056 6123560
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] Running: 4056 6123560
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] threadlist_wait_for_all wait failed
[1136] Running: 4056 6123560
[1136] Unload Plugin (gir_stop)D:\Program Files\Promixis\Girder5\plugins\0transport.dll
[1136] Unload Plugin 1 (gir_dui)D:\Program Files\Promixis\Girder5\plugins\0transport.dll
[1136] Unload Plugin (gir_close)D:\Program Files\Promixis\Girder5\plugins\0transport.dll
[1136] Unload Plugin (freelibrary)D:\Program Files\Promixis\Girder5\plugins\0transport.dll
[1136] Unload Plugin (gir_stop)D:\Program Files\Promixis\Girder5\plugins\AudioMixer.dll
[1136] Unload Plugin 1 (gir_dui)D:\Program Files\Promixis\Girder5\plugins\AudioMixer.dll
[1136] Unload Plugin (gir_close)D:\Program Files\Promixis\Girder5\plugins\AudioMixer.dll
[1136] Unload Plugin (freelibrary)D:\Program Files\Promixis\Girder5\plugins\AudioMixer.dll
[1136] Unload Plugin (gir_stop)D:\Program Files\Promixis\Girder5\plugins\ComSvr.dll
[1136] Unload Plugin 1 (gir_dui)D:\Program Files\Promixis\Girder5\plugins\ComSvr.dll
[1136] Unload Plugin (gir_close)D:\Program Files\Promixis\Girder5\plugins\ComSvr.dll
[1136] finalization NQ out
[1136] Stopped sharing an existing instance of FastMM.
[1136] WinHandle / Shared.dll finilization 1
[1136] WinHandle / Shared.dll finilization 2
[1136] FastMM has been uninstalled.


Let me know if you need more, I may add more debug to CustomWeather and try again.

[Ron]

This is very weird.

The thread is not stuck, or where there more loop debug logs?

Girder exits fine, meaning Lua is not stuck. The next release of G will include a debugger showing us the lua threads and their cpu usage, maybe that will be enlightening,

- Ron

[harleydude]

Ron,

That will be a tremendous help for us developers. Sometimes I think it is my scripts getting stuck in loops.

Any idea on the new release date?

[Ron]

It should be out this week. There is one final issue in the debugging libraries that I am trying to solve and then it can go out. Note that if a thread hangs even the debugger might not be able to get any information out as the global lua mutex might be held...

[Ron]

Just a side thought, is your temp-disk full?

[kanebullen]

Hi

I just thought I'd let you know that I found the problem that was causing Girder to go up to 100% CPU when using the Russound Plugin.

Interestingly, the problem is caused by the Serial-USB converter I was using. I've just gone and bought a different one, and everything is running perfectly (1% CPU)

The one I was using was a chinese chipset which was a cheap import from Hong Kong (Ebay special!) - known as a CH340 (or HL340)

Anyway, this may help someone out at a later date, so thought I'd post the info!

Cheers

Kane

[Rob H]

Thanks, that's useful to note for the future.

[Ron]

harleydude, can you run your tests with the attached lwinfunc.dll and auxilary.dll?

[harleydude]

Ron,

Latest logs. Ran 2hrs before locking.

LUA Console

19:54:05

CW:UpdateCheckAsync():Starting Local
CW:UpdateCheckAsync():ForecastConditions
CW:UpdateCheckAsync():DetailedForecastConditions
CW:UpdateCheckAsync():CurrentConditions
CW:UpdateCheckAsync():SatelliteMap
CW:UpdateCheckAsync():AnimatedSatelliteMap
CW:UpdateSatMapAnim():URL http://xml.customweather.com/xml?client=proximis_test&client_password=t3mp&product=maps&map_product=satellite&name=Garland,United States&anim=true&girder=7960 C:\DOCUME~1\RickJr\LOCALS~1\Temp\\CW SAT ANIMATED 1.GIF
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running
UpdateCheckAsync Already Running


DebugView Log

00012968 7:54:05 PM [3396] lua_URLDownloadToFile Looping Read 4162 bytes
00012969 7:54:05 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012970 7:54:05 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012971 7:54:05 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00012972 7:54:05 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012973 7:54:05 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012974 7:54:05 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012975 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012976 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012977 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00012978 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012979 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012980 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012981 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012982 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012983 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00012984 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012985 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012986 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012987 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012988 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00012989 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012990 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012991 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012992 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012993 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012994 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00012995 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012996 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012997 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012998 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00012999 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2040 bytes
00013000 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 848 bytes
00013001 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013002 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013003 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013004 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013005 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00013006 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013007 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013008 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013009 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013010 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013011 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00013012 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013013 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013014 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013015 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013016 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013017 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00013018 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013019 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013020 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013021 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013022 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00013023 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013024 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013025 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013026 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013027 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013028 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00013029 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013030 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013031 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013032 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013033 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013034 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00013035 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013036 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013037 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013038 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013039 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2040 bytes
00013040 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 848 bytes
00013041 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013042 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013043 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013044 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013045 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00013046 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013047 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013048 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013049 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013050 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013051 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1440 bytes
00013052 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013053 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013054 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013055 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2040 bytes
00013056 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013057 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013058 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013059 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2040 bytes
00013060 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013061 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013062 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013063 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2040 bytes
00013064 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013065 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013066 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2048 bytes
00013067 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 2040 bytes
00013068 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1736 bytes
00013069 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes
00013070 7:54:06 PM [3396] lua_URLDownloadToFile Looping Read 1448 bytes


It appears that output to DebugView stops, but the script stays locked.

[Ron]

Rick is there any way I could VNC into your machine? That might be faster then going back and forward...

[harleydude]

Do you want to VNC to it when it is happening or prior to that?

[Ron]

If I could recreate it during a VNC session that would be great.

[harleydude]

I will be home around 5:30 Central and get it setup and PM you the details.

[harleydude]

Well came home tonight and noticed that announcements were delayed by a few seconds longer than usual. Logged in to the server and saw that Girder had the CPU pegged again. Disabled CustomWeather and CPU drop to next to nothing.

Looks like CW is still causing some problems. :(

[Rob H]

:( That's not good - doesn't sound like a stuck thread either if you could successfully disable CW. Did CPU usage drop immediately after you disabled it?

[harleydude]

Yes it did.

[Ron]

I will look at that code again this week to see if something could be looping.