Has anyone here ever used the 4D Debug log that can be created by switching on

SET DATABASE PARAMETER(Debug log recording;x)

No? Yes? How useful was it?
Until recently i never even looked at it, too much data too little visible information.
That changed once I saw a nice little piece of code written by Justin Carr from Australia. Called DebugLogReader it does just what’s advertised on the box: It reads your log files and displays the data in a meaningful way.

As I was just tasked to optimize some code from a database I had not written (well not initially) I put it to the test and after some fiddling I was able to shave roughly 12 seconds off opening a product record. 12 Seconds is an eternity for users, especially when browsing through a selection!

That’s when I decided to extend this wonderful tool and with Justins kind permission I hereby present:

DebugLogReader 1.01

Well, as you are still here, you seem interested.

The tool is a compiled application for 4D V16 and can be downloaded from here:

Download DebugLogReader V 1.01

Once downloaded you just start it up, and after being prompted to create a datafile will be asked for a project name. Just enter it, don’t worry you can change it later and/or add more projects.

The Main Window

Next this wonderful screen will appear:

Well here it is already filled with data (the project name prominently on top), so I will give a quick run-down of the various elements, although I would expect them to be self-explaining:

• New Project will ask you to create a new datafile and re-launch the application with that file
• Switch Project will let you select another datafile with information from another project

Then you have the Settings section with 2 folder locations:

• Logs Folder is the path to the folder with the log files you desire to read
• Plugins Folder should point to the Plugins folder of your project

Click on the cute Select button behind an entry in order to choose the folder. You can switch the Log folder at any time if you store them in different locations or use the provided component AC_DebugLogToggle, more of that later.

If the application detects log files it does not yet know, the button

• Read (new) log files will let you start the import. Please be patient, it may take a while especially if your log contains multiple files. A progress bar will keep you entertained in the meantime.
• Available sessions will show a list of all debug session you already imported, clicking on one of these will show
• Processes in session with a quick info on the process number, the lines of code contained and when it was started, or at least seen for the first time in the log file. Clicking on the process name column will allow you to enter the name of the process in order to identify them later. Optional, not required, I usually don’t bother…

You can of course use these 3 buttons to clean up your data:

• Clear all data will remove all data from the project file
• Delete selected session will delete all data for the session you don’t want anymore
• Delete selected process will remove data for processes you might not be interested in

Diving in:

Double-Clicking a process will present you with 3 choices:

• Raw Data will display the debug log raw data, although in human readable form, well human developer readable form…
• Hierarchical View will present you with a hierarchical view of you method and command calls and will let you expand down into your processes
• Analyse Will show statistics on all methods, commands and plugin calls in the process and will let you dive into that data

now the details:

Raw Data

Will show you this window:

it shows all lines of the log for the selected process in chronological order.
Using the toggle buttons at the top you can filter with elements you want to see:

• Methods your own methods as well as any methods from components
• Commands all 4D commands
• Plugin Commands well, guess…
• Plugin Entry Points whenever a plugin called on 4d to get something

Also you can filter using the text box on the top, click in Go to trigger the search. Do I have to tell you, you can sort the columns? Oh well, just did it anyway.

Hierarchical view

will show this window:

Here you can see the actual flow of your code and dive into method calls drilling down to see hat is taking ump time (the numbers in the brackets are the microseconds it took to complete the call or command).

If you double-click a line (or if your top level has more than 50k lines) you will see this form with more details:

Here you can dive into any line that has a toggle icon in front. The top of the window will show your current path (as much as fits in there at least) and with the Back button you can move back up in your call history.

Analyse

Is what I find most helpful. Imagine you want to find out why a specific part of your code is slower than it should be, this is where analysts comes in as it will aggregate data on all instances of a method or command it finds in the log and will allow you to view this in an aggregated fashion thus giving a better impression of what is going on.

First you will see this window:

Here you can see all methods and commands found in the process log, the buttons on top will let you filter and search just as with the Raw Data view.
The difference here is that for example duration are the sums of all duration of a specific command or method, also showing min, max and average duration.

If you now double click on a specific method (or EXECUTE* command for that matter) you will see something like this:

The top list is your call stack so you don’t loose yourself, you can also double click on a line (but the last one obviously) to move back.
The second list shows all calls within the method you are currently looking at, again aggregated data for all instances of that method is displayed. The Share column shows a visual representation of where your code spends most of its time and
the third list shows all calls of that particular method or command.
Clicking on the Return to Stats button will get you back to the first page.

It is here where I was able to quickly find where I am inefficient in my code and thus really make a difference without having to spend ages pouring and tracing through my code.

How to invoke the log?

There are several options when starting the debug log with the Set Database Parameter command:

• Format = 4 is always the basis as it will write the log in a pretty format we can actually read
• Format + 8 will defer the writing of the log file, effectively making it asynchronous with makes a great difference in run times as your code will not have to wait for the actual writing of the log file. Useless if you try to debug a crash though!
• Format +2 will toggle writing of parameters. Your choice, sometimes these help. Keep in mind that only parameters passed to 4D commands are tracked, parameters to your own methods are ignored.

Quite surprising there is a funny bug in 4D that will mix up log files if sessions span more than one file and if you start a new session when you logging is beyond file number one. 4D will always start overwriting file #2 leaving higher files untouched if it does not need them.

I have written a tiny component that you can use to toggle debug log recording and that will move all files of a session into a folder with the current timestamp.

You can download it here for all major version of 4D:

• AC_DebugLogToggleV14
• AC_DebugLogToggleV15
• AC_DebugLogToggleV16

Just drop the one you need into your components and call

DEBUG_Toggle

it will check if the debug log is running ad if not, it will ask 2 questions:

• Is this an optimization or crash debug session click crash only if you want to use the debug log to find a crash, as selecting optimize will switch on asynchronous log writing
• Write parameters no need to explain that one do I ?

When toggling the the debug log to OFF, the component will create a folder 4DDebugLog within the Logs folder of your project (if it is not already there) and will move all log files to a new subfolder named by timestamp (i.e. 2017-02-13T115433)

Finally

I have added a toggle for the debug log to my final code so users can switch it it on or off whenever they feel there is a problem and i want to see what is going on. It works fine with compiled code thus making it a very useful tool for user support.

Questions will be answered whenever I get to it, suggestions, bug reports etc. directly to me please.

I hope you all enjoy this tool and can make good use of it, it sure has helped me a lot and please make sure to drop a big thanks to Justin Carr (find his email in the about box) for his superb work in creating the initial code base for this.