More fine grained control over ViewX logging

[BevanWeiss]

By default the ViewX logging is quite excessive.  Like it creates almost 7MB of log files to just open up a single mimic in an offline development system that I have.

This results in performance issues since the logging appears to be synchronous to other ViewX actions (like displaying the mimic, or allowing user interaction).  In addition, with lower performance desktop computers supplied by clients, this performance impact is magnified, to the point where a user can be waiting over a minute for a mimic navigation action to occur.

This currently results in the undesirable situation where we have no choice but to disable logging on these clients.

This means that when an issue occurs (i.e. a crash), we don't have any logging available to narrow down what caused it, or to assist in reproduction.

It would be good if ViewX had finer grained control over the level of ViewX logging applied.

These are the kind of entries that are filling up the log files, the majority of which do not appear to be important for typical issues.

2021-04-09 04:25:11.707 Default [13E4:01] [Interop] ScxMoniker[2579:/CMimic/!Config.Library.Symbols.Tabs.Horizontal - Top.1705] FinalRelease()
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [Doc 284] CDrwMimicDef Reading 6 animations
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [Doc 284] CDrwMimicDef Reading script
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [Doc 284] CDrwMimicDef Serialize [OUT]
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [Doc 39] CDrwMimicDef Clone complete
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [Doc 280] CDrwMimicDef Reading 3 animations
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [Doc 280] CDrwMimicDef Reading 1 animations
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [Doc 280] CDrwMimicDef Read Layer 5
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [Doc 280] CDrwMimicDef Reading 2 objects
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [DLL] DllGetClassObject( IN: ClassId {EEAD2009-0777-11D2-AF05-0000E82E7A14}, Iid IParseDisplayName )
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [DLL] DllGetClassObject( OUT: Hr 80004002 -> No such interface supported )
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [DLL] DllGetClassObject( IN: ClassId {EEAD2009-0777-11D2-AF05-0000E82E7A14}, Iid IClassFactory )
2021-04-09 04:25:11.707 Default [13E4:01] [Interop] [DLL] DllGetClassObject( OUT: Hr 0 -> Ok )

...

2021-04-09 04:28:24.575 Default [13E4:01] [Interop] [OPCDAGRP] [14] Item: Client 0, Time 09-APR-2021 04:28:24.000, Val VT_DATE 09-APR-2021 04:28:24.000, Qual 0xC0
2021-04-09 04:28:25.076 Default [13E4:18] [Interop] [SINK-THR] [59] Posting msg from localhost for client 12, hWnd 0x1402d4
2021-04-09 04:28:25.076 Default [13E4:01] [Interop] [SINK-APP] OnEvent client 12, Version 6.83.7742
2021-04-09 04:28:25.576 Default [13E4:18] [Interop] [SINK-THR] [59] Posting msg from localhost for client 14, hWnd 0x1402d4
2021-04-09 04:28:25.576 Default [13E4:01] [Interop] [SINK-APP] OnEvent client 14, Version 6.83.7742
2021-04-09 04:28:25.576 Default [13E4:01] [Interop] [OPCDAGRP] [14] hClientGroup 5, TransactionID 0, ItemCount 1
2021-04-09 04:28:25.576 Default [13E4:01] [Interop] [OPCDAGRP] [14] Item: Client 0, Time 09-APR-2021 04:28:25.001, Val VT_DATE 09-APR-2021 04:28:25.001, Qual 0xC0
2021-04-09 04:28:26.077 Default [13E4:18] [Interop] [SINK-THR] [59] Posting msg from localhost for client 12, hWnd 0x1402d4
2021-04-09 04:28:26.077 Default [13E4:01] [Interop] [SINK-APP] OnEvent client 12, Version 6.83.7742
2021-04-09 04:28:26.577 Default [13E4:18] [Interop] [SINK-THR] [59] Posting msg from localhost for client 14, hWnd 0x1402d4
2021-04-09 04:28:26.577 Default [13E4:01] [Interop] [SINK-APP] OnEvent client 14, Version 6.83.7742
2021-04-09 04:28:26.577 Default [13E4:01] [Interop] [OPCDAGRP] [14] hClientGroup 5, TransactionID 0, ItemCount 1
2021-04-09 04:28:26.577 Default [13E4:01] [Interop] [OPCDAGRP] [14] Item: Client 0, Time 09-APR-2021 04:28:26.002, Val VT_DATE 09-APR-2021 04:28:26.002, Qual 0xC0
2021-04-09 04:28:27.077 Default [13E4:18] [Interop] [SINK-THR] [59] Posting msg from localhost for client 12, hWnd 0x1402d4
2021-04-09 04:28:27.077 Default [13E4:01] [Interop] [SINK-APP] OnEvent client 12, Version 6.83.7742
2021-04-09 04:28:27.579 Default [13E4:18] [Interop] [SINK-THR] [59] Posting msg from localhost for client 14, hWnd 0x1402d4

I believe it would be better if there was the ability to only log 'Critical' events, like crashes etc as the mimic which triggered the crash, and a few other easily identifiable pieces of information.

Another level for 'Important' events, which would include operator actions, like which page they are navigating to, which object they click on the page, which context menu option they select, etc (plus those events from 'Critical' level).

[sbeadle]

Improvements were made to logging 7 months ago.

With ViewX log files, it was found that the logging from ViewX was not fully implemented and it was actually logging everything regardless of the logging level requested. A new registry entry for the LogLevel in ViewX has been added:

HKCU\Software\Schneider Electric\ClearSCADA\ViewX\LogLevel

There are bit field definitions for the ViewX log levels:

1 = Core

2 = MimicParam

4 = DataSource

8 = MimicPerf

16 = MimicContent

32 = HTTPLink

These logging levels are used throughout the code in ViewX so enabling or disabling the different levels should have noticeable effects on general ViewX performance depending on the users database and Mimics.

Some information gets logged regardless of the level, whereas other content only gets logged with VIEWXLOG_CORE or VIEWXLOG_DATASOURCE levels, and so on.

Does this help with the issue?

[BevanWeiss]

I reckon that just might do so.  Is the default logging level 'EVERYTHING'?

Maybe I just missed this setting in my last pass through the AU Tech Support team for the ViewX logging.  Although I did raise ViewX logging with them just recently.  So it might need to be included in an note somewhere (perhaps in the Release Notes, or even just an article in tprojects)...

I'll give it a try later in the week and see how it goes.

Thanks.

[BevanWeiss]

@sbeadle Hey Steve,

Unfortunately definitely not the improvement I was hoping for... when I've trimmed it all the way down to '1' (i.e. Core)

I'm getting millions of rows of:

2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1318, Handle 1487017
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1319, Handle 1487018
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1320, Handle 1487019
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1321, Handle 1487020
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1322, Handle 1487021
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1323, Handle 1487022
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1324, Handle 1487023
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1325, Handle 1487024
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1326, Handle 1487025
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1327, Handle 1487026
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1328, Handle 1487027
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1329, Handle 1487028
2021-04-29 07:09:02.351 Default [3168:01] [Interop] [OPCDAGRP] [12] Item 1330, Handle 1487029

That looks more like DataSource information to me.

Is there a way to validate that the registry setting was accepted?

This is from the Geo SCADA Expert 2020 October 2020 Update.

A 15MB log file after visiting two mimics... this won't work for me at this stage 😞