Slow window opening troubleshooting

Brian · November 16, 2021, 10:24pm

I’m trying to troubleshoot why one of my windows in my project takes longer and longer to open the longer the project is running. I’m on Ignition 7.9.6. What I’ve done so far is to put some print statements into the window events to log how long various things take. First, I added a custom property to the window’s root container. Then, in the visionWindowOpened event handler, I have this script:

ts = System.nanoTime()
system.gui.getParentWindow(event).getComponentForPath('Root Container').windowOpen = ts
print "opening window ", event.source, " at ", system.gui.getParentWindow(event).getComponentForPath('Root Container').windowOpen

This stuffs the nanosecond timestamp of when the window opened (first event that fires, as far as I can tell) into the custom property of the root container of the window. Then, I put code similar to the following in event handlers for my window, and a couple containers in the window:

ts = System.nanoTime()
startTS = system.gui.getParentWindow(event).getComponentForPath('Root Container').windowOpen

delay = (ts - startTS)/1000000
print "internalFrameActivated ", event.source, " after ", delay

What I’m finding is that it’s actually the internalFrameActivated event that is stretching out the delay. The rest of the window events happen pretty quickly after this one.

Is there any way to instrument the things that are happening during the time between visionWindowOpened and internalFrameActivated to try to track down what is causing the delay? I’ve put the delay printing code on a couple items, but everything seems to print after the internalFrameActivated is done.

The other odd thing about this is that right after the project is opened, I can switch to this window pretty quickly. It’s only after some use/time (haven’t been able to replicate exactly), the window open speed slows down. The window is part of a tab strip navigation system, and gets closed when navigating to a different tab.

pturmel · November 16, 2021, 11:19pm

Are you using Classic Charts with its .configureChart event? Anywhere in the app? If so, you are probably suffering from a huge memory leak. If so, you will need to upgrade to the latest 7.9.x.

Brian · November 16, 2021, 11:26pm

Mostly EasyCharts in this app. I do have one Classic Chart on a window (well, 4, one for each tab), but I don’t have any scripting on it.

No charts in the slow-opening window. I have a calendar, list box, template repeater, but no charts.

Also, the windows with charts open fine. It’s only this one window that lags after a while. Moving between the other windows is not affected.

I’d love to upgrade in general, but I need to do some legwork first. Lots of 32 bit clients (Windows and RPi) around here I did finally get rid of some large event scripts that I was using to talk to some legacy devices, so that road block is gone

pturmel · November 16, 2021, 11:28pm

Try snapshotting the diagnostic window’s memory chart while OK and then while bogged down.

Brian · November 16, 2021, 11:46pm

Screenshot taken right after switching to problematic window.

Console printout during the switch:

opening window  Employees  at  3053752845788534
internalFrameActivated  Employees  after  4180
4430 ms,  CalendarContainer , ancestor , Root Container
4436 ms,  ClockedInTabContainer , ancestor , Root Container
4441 ms,  Root Container , ancestor , javax.swing.JLayeredPane[null.layeredPane,0,0,1076x859,alignmentX=0.0,alignmentY=0.0,border=,flags=0,maximumSize=,minimumSize=,preferredSize=,optimizedDrawingPossible=true]
4449 ms,  Employees , ancestor , VisionApp[Shop_Floor]
4457 ms,  Employees , _WhenInFocusedWindow , {ctrl pressed SPACE=ctrl pressed SPACE, shift pressed ESCAPE=shift pressed ESCAPE, pressed ESCAPE=pressed ESCAPE}
4465 ms,  Root Container , windowOpen , 3053752845788534
4484 ms,  Root Container , priorPayPeriodStart$Quality , Good
4490 ms,  Root Container , serverTime$Quality , Good
4496 ms,  Root Container , payPeriodEnd$Quality , Good
4501 ms,  Root Container , payPeriodStart$Quality , Good
4505 ms,  CalendarContainer , visible$Quality , Good
4510 ms,  ClockedInTabContainer , visible$Quality , Good
4515 ms,  Root Container , componentRunning , True
4520 ms,  CalendarContainer , componentRunning , True
4546 ms,  ClockedInTabContainer , componentRunning , True
4657 ms,  Employees , selected , True

Relaunched the client, screenshot after switching to problematic window:

Console printout during the switch:

opening window  Employees  at  3054058487070044
internalFrameOpened  Employees  after  107
internalFrameActivated  Employees  after  118
278 ms,  Root Container , windowOpen , 3054058487070044
335 ms,  CalendarContainer , qualityList , [com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@139acef]
339 ms,  CalendarContainer , dataQuality , 192
343 ms,  CalendarContainer , visible$Quality , Good
350 ms,  ClockedInTabContainer , qualityList , [com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@b1c4db]
353 ms,  ClockedInTabContainer , dataQuality , 192
356 ms,  ClockedInTabContainer , visible$Quality , Good
372 ms,  Root Container , qualityList , [com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@12ec4b0, com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@12a1d0f, com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@1f534ee, com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@15cbfd7]
375 ms,  Root Container , dataQuality , 192
378 ms,  Root Container , priorPayPeriodStart$Quality , Good
383 ms,  Root Container , dataQuality , 600
387 ms,  Root Container , serverTime$Quality , Unknown
391 ms,  Root Container , payPeriodEnd$Quality , Good
394 ms,  Root Container , payPeriodStart$Quality , Unknown
396 ms,  Root Container , componentRunning , True
402 ms,  CalendarContainer , componentRunning , True
425 ms,  ClockedInTabContainer , componentRunning , True
441 ms,  Employees , layeredContainerLayer , 0
448 ms,  Employees , selected , True
453 ms,  Employees , _WhenInFocusedWindow , {ctrl pressed SPACE=ctrl pressed SPACE, shift pressed ESCAPE=shift pressed ESCAPE, pressed ESCAPE=pressed ESCAPE}
457 ms,  CalendarContainer , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=0.0,y=181.0,w=790.0,h=469.0]
462 ms,  ClockedInTabContainer , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=0.0,y=181.0,w=790.0,h=469.0]
465 ms,  CalendarContainer , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=15.99231,y=239.19847,w=1044.0154,h=619.8015]
468 ms,  CalendarContainer , font , java.awt.Font[family=Dialog,name=Dialog,style=plain,size=16]
472 ms,  ClockedInTabContainer , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=15.99231,y=239.19847,w=1044.0154,h=619.8015]
475 ms,  ClockedInTabContainer , font , java.awt.Font[family=Dialog,name=Dialog,style=plain,size=16]
477 ms,  Employees , maximum , True
544 ms,  Root Container , priorPayPeriodStart$Quality , Unknown
547 ms,  Root Container , payPeriodEnd$Quality , Unknown
703 ms,  Root Container , serverTime$Quality , Good
707 ms,  Root Container , payPeriodStart$Quality , Good
711 ms,  Root Container , priorPayPeriodStart$Quality , Good
715 ms,  Root Container , dataQuality , 192
719 ms,  Root Container , payPeriodEnd$Quality , Good

pturmel · November 17, 2021, 12:08am

Jeez, dude, give your clients more RAM. (Project properties.)

Brian · November 17, 2021, 12:15am

Increased the max from 256 to 512. I’ll see what that does for it tomorrow.

pturmel · November 17, 2021, 12:26am

As you are on v7.9.6, you might also want to add this:

 jvm-args="-XX:+UseG1GC"

to your local client launcher command lines.

Brian · November 18, 2021, 5:23pm

Well, a day later and my window is slow again (might have taken longer to become slow with the bump in memory, not sure. I don’t have a good way to replicate it, and it’s a slow progression.)

It doesn’t look like I’m bumping into my memory limit (the time of the window switch is at the red line):

Console printout during the switch:

opening window  Employees  at  3203000447868224
internalFrameActivated  Employees  after  3604
3695 ms,  PMIButton: Log In , ancestor , Root Container
3708 ms,  CalendarContainer , ancestor , Root Container
3715 ms,  ClockedInTabContainer , ancestor , Root Container
3724 ms,  Root Container , ancestor , javax.swing.JLayeredPane[null.layeredPane,0,0,1076x859,alignmentX=0.0,alignmentY=0.0,border=,flags=0,maximumSize=,minimumSize=,preferredSize=,optimizedDrawingPossible=true]
3731 ms,  Employees , ancestor , VisionApp[Shop_Floor]
3739 ms,  Employees , _WhenInFocusedWindow , {ctrl pressed SPACE=ctrl pressed SPACE, shift pressed ESCAPE=shift pressed ESCAPE, pressed ESCAPE=pressed ESCAPE}
3746 ms,  Root Container , windowOpen , 3203000447868224
3930 ms,  CalendarContainer , visible$Quality , Good
3941 ms,  Root Container , priorPayPeriodStart$Quality , Good
3946 ms,  Root Container , serverTime$Quality , Good
3951 ms,  Root Container , payPeriodEnd$Quality , Good
3956 ms,  Root Container , payPeriodStart$Quality , Good
3960 ms,  ClockedInTabContainer , visible$Quality , Good
3965 ms,  Root Container , componentRunning , True
3970 ms,  PMIButton: Log In , componentRunning , True
3979 ms,  CalendarContainer , componentRunning , True
4006 ms,  ClockedInTabContainer , componentRunning , True
4070 ms,  PMIButton: Log In , text , Log In
4077 ms,  Employees , selected , True

The other windows in this application remain pretty snappy when switching, even with this one being slow. Not sure whether it’s relevant, but the whole UI freezes during this pause, including the diagnostics screen.

I haven’t had a chance to add the G1GC option to my client launchers, but I’m not sure if it would help, as I’m not sure I’m running into memory pressure?

PGriffith · November 18, 2021, 5:34pm

Try putting the WindowCache logger to debug then opening this window (ideally, before opening it the first time). It’ll give you an elapsed time for the actual deserialization of the window contents.

There’s a degenerate performance bug in Vision deserialization of datasets that may be affecting you here, but unfortunately it’s not fixed until fairly recently on the 8.1 line. If you do have any datasets serialized on this window, that may explain slow serialization, which may explain slow window opening.

zxcslo · November 18, 2021, 5:48pm

There is no ‘WindowCache’ logger in v8.1.7…?

nminchin · November 18, 2021, 5:50pm

Paul is talking about setting the logger in the client itself ie inside the diagnostics viewer

Brian · November 18, 2021, 5:50pm

Where does that log to?

PGriffith · November 18, 2021, 5:53pm

Client Diagnostics → Console. Ctrl + Shift + F7 to open it if you’ve got the client menubar or help toolbar disabled.

Brian · November 18, 2021, 5:57pm

This one?

Changed to debug, then started switching windows, but the only thing that shows up in the console is the print statements that I added to my window. Is there anything else I need to do to ‘apply’ the setting? Close the diagnostic window, then reopen?

Edit: I switched to one of the other windows and noticed a debug message for that one, so I guess the setting is working. It’s just that the window must not need to be decoded in this case (while it’s running slow). There’s no entry for that window when switching to it.

Brian · November 18, 2021, 6:05pm

Logging out and logging back in (didn’t close the app, just log out/in) got the debug statement to fire for that window. I’m also back to a fast opening window.

12:03:46.263 [AWT-EventQueue-2] DEBUG com.inductiveautomation.factorypmi.application.model.WindowCache - Decoding window Employees finished. (205ms)
opening window  Employees  at  3206335452744669
internalFrameOpened  Employees  after  83
internalFrameActivated  Employees  after  92
189 ms,  Root Container , windowOpen , 3206335452744669
199 ms,  ClockedInTabContainer , qualityList , [com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@55e09f]
204 ms,  ClockedInTabContainer , dataQuality , 192
210 ms,  ClockedInTabContainer , visible$Quality , Good
251 ms,  Root Container , qualityList , [com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@58f16b, com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@1abbd94, com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@1924c00, com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@138d0da]
257 ms,  Root Container , dataQuality , 192
263 ms,  Root Container , priorPayPeriodStart$Quality , Good
268 ms,  Root Container , dataQuality , 600
272 ms,  Root Container , serverTime$Quality , Unknown
277 ms,  Root Container , payPeriodEnd$Quality , Good
282 ms,  Root Container , payPeriodStart$Quality , Unknown
291 ms,  CalendarContainer , qualityList , [com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@11854b5]
296 ms,  CalendarContainer , dataQuality , 192
301 ms,  CalendarContainer , visible$Quality , Good
306 ms,  Root Container , componentRunning , True
315 ms,  PMIButton: Log In , componentRunning , True
323 ms,  CalendarContainer , componentRunning , True
354 ms,  ClockedInTabContainer , componentRunning , True
361 ms,  PMIButton: Log In , text , Log In
371 ms,  Employees , layeredContainerLayer , 0
375 ms,  Employees , selected , True
381 ms,  Employees , _WhenInFocusedWindow , {ctrl pressed SPACE=ctrl pressed SPACE, shift pressed ESCAPE=shift pressed ESCAPE, pressed ESCAPE=pressed ESCAPE}
387 ms,  PMIButton: Log In , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=89.0,y=50.0,w=89.0,h=37.0]
393 ms,  PMIButton: Log In , font , java.awt.Font[family=Dialog,name=Dialog,style=plain,size=18]
399 ms,  CalendarContainer , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=0.0,y=181.0,w=790.0,h=469.0]
404 ms,  ClockedInTabContainer , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=0.0,y=181.0,w=790.0,h=469.0]
409 ms,  PMIButton: Log In , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=133.60922,y=66.07693,w=117.61693,h=48.89691]
413 ms,  PMIButton: Log In , font , java.awt.Font[family=Dialog,name=Dialog,style=plain,size=24]
418 ms,  CalendarContainer , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=15.99231,y=239.19847,w=1044.0154,h=619.8015]
422 ms,  CalendarContainer , font , java.awt.Font[family=Dialog,name=Dialog,style=plain,size=16]
427 ms,  ClockedInTabContainer , vision.bounds2d , java.awt.geom.Rectangle2D$Float[x=15.99231,y=239.19847,w=1044.0154,h=619.8015]
432 ms,  ClockedInTabContainer , font , java.awt.Font[family=Dialog,name=Dialog,style=plain,size=16]
438 ms,  Employees , maximum , True
469 ms,  Root Container , priorPayPeriodStart$Quality , Unknown
473 ms,  Root Container , payPeriodEnd$Quality , Unknown
491 ms,  PMIButton: Log In , qualityList , [com.inductiveautomation.factorypmi.application.components.overlay.OverlayUtility$PropertyQualityEntry@149415f]
498 ms,  PMIButton: Log In , dataQuality , 192
615 ms,  Root Container , serverTime$Quality , Good
624 ms,  Root Container , payPeriodStart$Quality , Good
631 ms,  Root Container , priorPayPeriodStart$Quality , Good
637 ms,  Root Container , dataQuality , 192
643 ms,  Root Container , payPeriodEnd$Quality , Good

PGriffith · November 18, 2021, 6:24pm

What’s on this window that’s slow - any charts, tables, etc that might bring in a lot of data?
What’s the cache policy set to for the window?

The WindowCache on TRACE might be helpful to leave on for a while, as you navigate around things. How consistently does this ‘slow window’ behavior happen?
It also won’t help you on 7.9, but in 8.1.12 we’re adding an automatic thread dump process when we detect the main GUI thread is blocked for too long.

Brian · November 18, 2021, 6:38pm

Cache policy is set to Always (thought that might help when I was first troubleshooting this ).

I have a couple of lists (about 2 dozen items), a calendar object (probably less than 100 items on that), another list with basically the same items as the calendar presented in a different way), template repeater with 25ish instances of a fairly small template. Overall, I wouldn’t think there’s a lot of data here, compared to an EasyChart with several pens.

I can leave the WindowCache on Trace, it doesn’t look like it spams the log that much. I did notice some Binding debuggers that look interesting. Those give me events in between the window loading print statement and the internalFrameActivated print statement. They’re pretty noisy, so I’ll leave that one on Info until my window starts slowing down again.

It’s consistent in that it will eventually show up. However, as it’s pretty simple to fix by just relaunching the client, I usually deal with it that way. The reason I’m looking into it is that some of my operators don’t know how to do that on the touchscreens I have on the shop floor. Eventually the lag is so bad that they think the touch didn’t register to switch to that screen, so they try switching to something else, then back again, which just makes it lag twice.

Because I’m just starting to dive into this a little deeper, I don’t have a reliable way to make this show up on purpose other than to just wait and use the app. At least, so far. Also, the slowdown is gradual. Before I put some logging statements in, I was never sure if it was just my own perception that it was getting worse, at least in the short term. At some point it becomes obvious that the window is taking 3 seconds to load, and it’s not just something else running on my computer that’s the problem.

Brian · November 18, 2021, 7:19pm

I was able to get it running slowly again (need to try replicating the method to see if it’s repeatable). In the meantime, the binding logs set to Debug are somewhat interesting. It looks like there’s some sort of delay after the initial bindings are processed and when the internalFrameActivated event is fired. Here’s the latest console log, note the long gap between the internalFrameActivated message and the previous entry:

13:14:20.933  opening window  Employees  at  3210569969308434
13:14:20.935 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=VacationHoursContainer,property=currentAvailableHours] Expression ran, value=0, quality=Good
13:14:20.936 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=VacationHoursContainer,property=currentAvailableAsOfDate] Expression ran, value=Fri Jan 01 00:00:00 CST 2021, quality=Good
13:14:20.936 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=VacationHoursContainer,property=visible] Expression ran, value=false, quality=Good
13:14:20.937 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Delete,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.937 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=HolidayContainer,property=visible] Expression ran, value=false, quality=Good
13:14:20.937 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=DeleteRowButton,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.938 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Month View,property=month] Expression ran, value=11, quality=Good
13:14:20.938 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Month View,property=beginDateRange] Expression ran, value=Mon Oct 25 00:00:00 CDT 2021, quality=Good
13:14:20.939 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Month View,property=endDateRange] Expression ran, value=Wed Dec 15 00:00:00 CST 2021, quality=Good
13:14:20.939 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Month View,property=year] Expression ran, value=2021, quality=Good
13:14:20.939 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Save,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.940 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=CalloutContainer,property=visible] Expression ran, value=false, quality=Good
13:14:20.940 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=SupClockWorkerIn,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.941 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=SaveChangesButton,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.941 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Save,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.941 [AWT-EventQueue-2] DEBUG vision.binding.tag-binding - Subscribing to "Employees/ClockedIn" (ClockedInList.data)
13:14:20.942 [AWT-EventQueue-2] DEBUG vision.binding.tag-binding - [component=ClockedInList,property=data] Tag Employees/ClockedIn changed, value=[Dataset [18R ? 2C], Good, Thu Nov 18 13:14:12 CST 2021]
13:14:20.942 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=ClockedInList,property=selectedID] Expression ran, value=-1, quality=Good
13:14:20.943 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Clock in,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.943 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Tab Strip,property=hideTabs] Expression ran, value=true, quality=Good
13:14:20.944 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Delete,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.944 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Numeric Label,property=value] Expression ran, value=0, quality=Good
13:14:20.944 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Label,property=text] Expression ran, value=Vacation Remaining - 0 hrs, quality=Good
13:14:20.945 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Numeric Label 2,property=value] Expression ran, value=0, quality=Good
13:14:20.945 [AWT-EventQueue-2] DEBUG vision.binding.tag-binding - Subscribing to "Employees/RecentActivity" (Table.data)
13:14:20.945 [AWT-EventQueue-2] DEBUG vision.binding.tag-binding - [component=Table,property=data] Tag Employees/RecentActivity changed, value=[Dataset [20R ? 3C], Good, Thu Nov 18 13:14:12 CST 2021]
13:14:20.946 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=TimeClockLogTable,property=selectedLogId] Expression ran, value=null, quality=Good
13:14:20.946 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=TimeClockLogTable,property=selectedClockOut] Expression ran, value=null, quality=Good
13:14:20.947 [AWT-EventQueue-2] DEBUG vision.binding.property-binding - [component=ClockOutEditor,property=date] Source value changed, new value=null [Good]
13:14:20.947 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=TimeClockLogTable,property=selectedClockIn] Expression ran, value=null, quality=Good
13:14:20.947 [AWT-EventQueue-2] DEBUG vision.binding.property-binding - [component=ClockInEditor,property=date] Source value changed, new value=null [Good]
13:14:20.948 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Delete,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.948 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=CalendarContainer,property=visible] Expression ran, value=false, quality=Good
13:14:20.950 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=ClockedInTabContainer,property=visible] Expression ran, value=true, quality=Good
13:14:20.950 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=SupClockWorkerOut,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.951 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=BulkCalloutUpdate,property=visible] Expression ran, value=false, quality=Good
13:14:20.951 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=AddRowButton,property=componentEnabled] Expression ran, value=true, quality=Good
13:14:20.952 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=AsOfDate,property=date] Expression ran, value=Thu Nov 18 13:14:20 CST 2021, quality=Good
13:14:20.952 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=VacationContainer,property=visible] Expression ran, value=false, quality=Good
13:14:20.952 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Save,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.953 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Clock Out,property=componentEnabled] Expression ran, value=false, quality=Good
13:14:20.953 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Label,property=text] Expression ran, value=, quality=Good
13:14:20.953 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Root Container,property=priorPayPeriodStart] Expression ran, value=Mon Nov 08 00:00:00 CST 2021, quality=Good
13:14:20.954 [AWT-EventQueue-2] DEBUG vision.binding.tag-binding - Subscribing to "[System]Gateway/CurrentDateTime" (Root Container.serverTime)
13:14:20.954 [AWT-EventQueue-2] DEBUG vision.binding.tag-binding - [component=Root Container,property=serverTime] Tag [System]Gateway/CurrentDateTime changed, value=[Thu Nov 18 13:14:07 CST 2021, Good, Thu Nov 18 13:14:07 CST 2021]
13:14:20.954 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Root Container,property=payPeriodEnd] Expression ran, value=Mon Nov 22 00:00:00 CST 2021, quality=Good
13:14:20.955 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=Root Container,property=payPeriodStart] Expression ran, value=Mon Nov 15 00:00:00 CST 2021, quality=Good
13:14:20.955 [AWT-EventQueue-2] DEBUG vision.binding.expr-binding - [component=AdjustEmployeeTimeTabContainer,property=visible] Expression ran, value=false, quality=Good
13:14:27.488  internalFrameActivated  Employees  after  6552
13:14:27.494 [AWT-EventQueue-2] DEBUG vision.binding.tag-binding - [component=Tabs,property=selectedTab] Tag [System]Client/User/CurrentWindow changed, value=[Main Windows/Employees, Good, Thu Nov 18 13:14:27 CST 2021]
6594 ms,  PMIButton: Log In , ancestor , Root Container
6597 ms,  CalendarContainer , ancestor , Root Container
6599 ms,  ClockedInTabContainer , ancestor , Root Container

Is there anyway to increase the scrollback of the console? I tried switching the binding log to trace, but the stuff I’m interested in gets pushed off the stack too quickly to catch.

Also, what’s going on after bindings but before internalFrameActivation? Any other useful logs I might be able to turn on?

pturmel · November 18, 2021, 7:47pm

Your client laucher log file will contain the final java command line used to run the real client. You can paste that into a terminal window (set to a large scrollback) to run with terminal logging.