Since the sad demise of Revelation's article on the subject, there seems to be no quick reference guide available for the various kinds of log that can be created by OpenInsight to assist in debugging strange occurrences and things that go bump in the night.
As a service to the Rev community we therefore offer up our guide to all things log related. Speaking of logs, my best friend at school was nicknamed "Beaver". Steven Norwood. Oh the fun we had in maths lessons (this was pre-calculator days so we had to use log books)... Anyway
Event Logs
These logs are initiated when the "Start Log" button is pressed on the engine. The log file is created under the OpenInsight subdirectory.
Version 9
The file is named OELOGNNN.LOG and will roll over at 1000.
The log will contain every event triggered and all programs run not called from BASIC+ along with the passed parameters. For example
Start OpenEngine log - 2/24/2024 13:55:03
******************************************************************************
Begin processing time: 2/24/2024 13:55:10
RUN REPOSITORY 'WRITE', #1, #2, #3, #4, #5, #6, #7, #8, #9, #10, #11
#1: 'SYSPROG*OIWIN**ZZ_TEST'
#2: '0'
#3: ''
#4: ''
#5: ''
#6: ''
#7: ''
#8: ''
#9: ''
#10: 'ZZ_TEST'
#11: '300þ1þÿZZ_TESTýýWINDOWýý574ý258ý-484ý-311ýUntitled...'
Stop processing time: 2/24/2024 13:55:10
Execution time: 250 milliseconds.
Execution status: successful.
******************************************************************************
******************************************************************************
Begin processing time: 2/24/2024 13:55:10
RUN RUN_EVENT 'SYSPROG*OIWIN', 'ZZ_TEST.EDITLINE_1', 'EDITFIELD', 'GOTFOCUS*3*SYSPROG*GOTFOCUS..OIWIN*', 'ZZ_TEST.EDITLINE_1'
Stop processing time: 2/24/2024 13:55:10
Execution time: 46 milliseconds.
Execution status: successful.
******************************************************************************
The program's parameters are listed individually whereas the parameters for the event are passed in line. It should be noted that the engine log only logs programs that are not called directly from Basic+ so it is not as useful as it might seem for debugging.
Version 10
The file is named REVENGINENNN.LOG and will roll over at 1000.
The log will contain every event triggered with the passed parameters. For example
Start RevEngine A log - 2/24/2024 14:09:40
******************************************************************************
Begin processing time: 2/24/2024 14:09:45
RUN RUN_EVENT 'SYSPROG*OIWIN','RTI_IDE','WINDOW','ACTIVATED*2*SYSPROG*ACTIVATED.WINDOW.OIWIN*'
Stop processing time: 2/24/2024 14:09:45
Execution time: 16 milliseconds.
Execution status: successful.
******************************************************************************
Due to the fact that OpenInsight is now written in OpenInsight, all program calls originate from Basic+ so we no longer see programs being launched. Previously the various tools were external executables that relied upon calls to the engine to execute Basic+ code. These calls could be tracked in the log. Now that the tools are written in OI they don't make calls to the engine to execute code, they just call the code directly.
Profile Logs
As the name suggests, these logs record every single program called and returned to, along with granular timings, whilst the logs are active. In OI 9 these logs can only be recorded for the entirety of the OI session. In OI 10 it is possible to toggle them. In both versions the creation of a dummy text file in the OpenInsight subdirectory is required to record the log for the session.
Once you have this log it is possible to analyse the information to zoom in on where you may be experiencing speed issues, recursive code et al.
NB These logs slow the program speed down exponentially so it is a good idea to remove the dummy text file when it is no longer used (for example after you have started logging).
Version 9
To trigger the recording of a log simply create a text file called OEPROFILE.LOG before logging into OpenInsight. The system will create a file called OEPROFILE_MACHINENAME_PROCESSNUMBER.LOG. All timings in the log are in milliseconds - but only to a granularity of 16ms - hence the zeroes in the log.
As an example of a log starting OpenInsight here's the first few lines -
LOAD_SYSPROGDBT 0
RTP57 16
GETNETWORKTYPE 16
GETNETWORKTYPE 31 15
RTP57A 31
RTP57A 47 16
RTP57A 47
RTP57A 47 0
RTP57A 47
RTP57A 47 0
RTP57 47 31
RTP50 47
RTP50 47 0
What this tells us is that the program LOAD_SYSPROGDBT has started, and the first thing it did at tick 16, was to call RTP57, which in turn called GETNETWORKTYPE which took 15 ticks to complete. Some quick calls follow - some too fast to measure, until RTP57 exits 31 ticks after it started.
For reference here is another section where RUN_EVENT is referenced.
RUN_EVENT 2044
RTP27 2044
GETOISTATE 2044
GETOISTATE 2044 0
RTP57 2044
RTP57A 2044
RTP57A 2044 0
RTP57 2044 0
RTP27 2044 0
This will become relevant in the Version 10 section.
Whilst the log is useful, there are no tools provided for consuming it.
Version 10
To trigger the recording of a log simply create a text file called REVPROFILE.LOG before logging into OpenInsight. The system will create a file called REVPROFILE_MACHINENAME_PROCESSNUMBER.LOG.
As an example of a log starting OpenInsight here's the first few lines -
LOAD_SYSPROGDBT 27.36
RTP57 32.16
GETNETWORKTYPE 32.23
GETNETWORKTYPE 33.95 1.72
MSWIN_GETUSERNAME 33.99
MSWIN_GETUSERNAME 34.79 0.79
MSWIN_GETCURRENTPROCESSID 34.83
MSWIN_GETCURRENTPROCESSID 34.85 0.02
RTP57A 34.88
RTP57A 35.58 0.71
RTP57A 35.61
RTP57A 35.63 0.01
RTP57A 35.64
RTP57A 35.66 0.02
RTP57 35.69 3.53
RTP50 35.71
RTP50 35.73 0.02
The first thing that jumps out is that the timings are now to two decimals places, and they're no longer in ticks, rather they're in 0.01ms. So 1,600 times more granular.
The second thing that jumps out is when looking at a RUN_EVENT call -
RUN_EVENT 5153.86 ("SYSTEM", "LOGIN", "1", "SYSPROG", "SYSPROG", "SYSPROG")
RTP27 5153.87
GETOISTATE 5153.88
GETOISTATE 5153.88 0.00
We are now actually provided with what RUN_EVENT was doing.
Version 10 also has an analysis tool for the log files AND provides for manipulating the logging programmatically. Rather than reinvent the wheel we just refer you to the source.
Linear Hash Logs
These logs provide a record of every single file i/o operation performed at the workstation doing the logging. As with profile logging, linear hash logging is initiated by the creation of a specifically named file at the OpenInsight location. Unlike with profile logging, linear hash logging at the client is performed only for the first person to log in after the creation of the trigger table, so there is no performance impact on other users. If you wish to record all file i/o operations for all service users then server logs should be used instead qv but be warned these are very verbose so get very big very quickly.
UD3
Client
The trigger file in this case is LH3.LOG.
As an example of an LH3.LOG file, here's the first few lines
SN REVMEDIA OK
SU OK
UL 0 OK
OP REPOSIX 1 OK
OP REVDICT 2 OK
OP REVREPOS 3 OK
LO 3 U47961 OK
UL 3 U47961 OK
LO 3 U47961 OK
SU OK
OP REVMEDIA 0 OK
OP DATAVOL\REVMEDIA 4 OK
OP AREV_DIR\REVMEDIA 5 OK
OP O4WFILES\REVMEDIA 6 OK
RO 0 SYSOBJ*GLOBAL OK
OP REV30000 7 OK
Each line represents a single i/o operation, with the first value being an opcode that determines the subsequent parameters.
Looking at some of the obvious operations, OP REVMEDIA 0 OK, means open the REVMEDIA file to handle 0. Then RO 0 SYSOBJ*GLOBAL OK, means make a cached read (READO) of the file entry for SYSOBJ*GLOBAL from file handle 0 - the REVMEDIA map.
Regretfully there are no system tools to analyse the log files.
Server
The trigger file in this case is LH.LOG.
As an example of an LH.LOG, here's an exercise for the reader....
UD4
Client
The trigger file in this case is LH4.LOG.
As an example of an LH4.LOG file, here's the first few lines
SN REVMEDIA OK SU OK UL 0 OK OP REPOSIX 1 OK OP REVDICT 2 OK OP REVREPOS 3 OK LO 3 U47961 OK UL 3 U47961 OK LO 3 U47961 OK SU OK OP REVMEDIA 0 OK OP DATAVOL\REVMEDIA 4 OK OP AREV_DIR\REVMEDIA 5 OK OP O4WFILES\REVMEDIA 6 OK RO 0 SYSOBJ*GLOBAL OK OP REV30000 7 OK
Notice the subtle difference from the UD3 log? That's right, there isn't one.
Server
The trigger file in this case is LH47SRVC.LOG.
As an example of an LH47SRVC.LOG, here's the first few lines, in a smaller font to prevent wrapping - it is verbose
Initialize...done.
Start pending...Running.
Connect...client 0.
0:Version Check...done.
0SRVC Connecting...passed parameter X99999999|0
Validating...bValid 1, bAuthorized 1
:Open Session,X99999999,250...session 0.
0,0,ZZ\ZZ15\REVMEDIA:Open File (resolved to E:\ZZ\ZZ15\REVMEDIAðNf)...file 0.
0,0:Unlock All...done.
There are some gotchas analysing these files as the first two lines are CRLF delimited and all subsequent are LF delimited, but the verbosity of the text makes understanding what is going on a lot easier.
UD5
Client
The trigger file in this case is REVLH.LOG.
As an example of a REVLH.LOG file, here's the first few lines
SN
REVMEDIASU OK
UL 0 OK
OP REPOSIX 1 OK
OP REVDICT 2 OK
OP REVREPOS 3 OK
LO 3 U50707 OK
SU OK
OP AREV_DIR\REVMEDIA 4 OK
OP LH_DIST\REVMEDIA 5 OK
OP O4WFILES\REVMEDIA 6 OK
OP REVMEDIA 0 OK
OP DATAVOL\REVMEDIA 7 OK
OP FAQS\REVMEDIA 8 OK
RO 0 SYSOBJ*GLOBAL OK
This time there IS a subtle difference - there's a weird bug where it puts the CRLF after the SN and swallows the OK., Presumably an offset issue in the osbwrite. Also the login semaphore logic is slightly different. Beyond that the log file follows the pattern of the others.
Random trivia - logging in and out of 9 generates a 10Kb log file. Doing the same on 10 generates a 168Kb log file. Now that OI is written in OI there's a lot more i/o needed to bootstrap the system.
Useful random trivia - you can restrict the operations recorded by creating a file called REVLH.DETAILS containing a comma delimited list of the opcodes you wish to capture. The log will then only contain those opcodes and be correspondingly quicker to generate.
Server
The trigger file in this case is REVLHSRVC.LOG.
As an example of a REVLHSRVC.LOG, here's the first few lines, with wrapping left in place.
Initialize...done.
Start pending...
VSS: UDVSSWriter Initializing...
Running.
[156699562] initialized
[156699562] [156711625] Connect... [156711625] client 0.
[156711625] [156711625] 0 [156711625] :Version Check... [156711625] OK; secure channel check (0\0)... [156711625] done.
[156711625] [156711625] 0 [156711625] NUL Connecting...passed parameter W99999999|1
[156711625] [156711625] Validating...bValid 1, bAuthorized 1
[156711625] [156711625] :Open Session [156711625] , [156711625] W [156711625] 9 [156711625] 9 [156711625] 9 [156711625] 9 [156711625] 9 [156711625] 9 [156711625] 9 [156711625] 9 [156711625] ,9 [156711625] ... [156711625] session 0.
[156711625] [156711625] 0 [156711625] ,0 [156711625] ,E:\OpenInsight\UD Test\REVMEDIA [156711625] :Open File (resolved to E:\OpenInsight\UD Test\REVMEDIA)... [156711640] file 0.
[156711640] [156711640] 0 [156711640] ,0 [156711640] :Unlock All... [156711640] done.
[156711640] [156711640] 0 [156711640] ,0 [156711640] ,E:\OpenInsight\UD Test\REPOSIX [156711640] :Open File (resolved to E:\OpenInsight\UD Test\REPOSIX)... [156711640] file 1.
[156711640] [156711640] 0 [156711640] ,0 [156711640] ,E:\OpenInsight\UD Test\REVDICT [156711640] :Open File (resolved to E:\OpenInsight\UD Test\REVDICT)... [156711640] file 2.
[156711640] [156711640] 0 [156711640] ,0 [156711640] ,E:\OpenInsight\UD Test\REVREPOS [156711640] :Open File (resolved to E:\OpenInsight\UD Test\REVREPOS)... [156711640] file 3.
[156711640] [156711640] 0 [156711640] ,0 [156711640] ,E:\OpenInsight\UD Test\REVMEDIA [156711640] :Open File (resolved to E:\OpenInsight\UD Test\REVMEDIA)... [156711640] file 0.
There are some gotchas analysing these files as all lines are CRLF delimited apart from the VSS line and the Running line which are CR delimited, but the verbosity of the text makes understanding what is going on a lot easier.
Additional Tools
A big shout out to Revelation who made us aware of an additional tool allowing you to observe LH Statistics directly from the workstation. Not only that - you can dynamically turn linear hash logging on or off from the tool.
To use EXEC RTI_LH_INFO_VIEWER at TCL and the following window displays -
There is lots of information available to you here so explore at leisure! To start logging simply select "Client" or "Server" from the "Logger" dropdown and then press "Go". To stop logging, select "Stop Logging" from the "Action" dropdown and then press "Go".
Finally - log files can get a bit overwhelming so if you want to set a "place marker" in a linear hash log, just read a non-existent row using an easily recognisable dummy row id like "ZZ_STARTS_HERE" then you can search the log for that without wading through lots of extraneous stuff.
| Making Databases Happen |
UK +44 (0) 20 8912 1010 USA +1 267 238 3814 |