jBASE Profiling

This section describes the new jBASE 4.1 mechanisms for controlling certain profiling tools.

This profiling mechanism allows versatility when the output logs are stored and hot spot profiling in C and jBASE BASIC code. The functionality can be applied dynamically to currently executing applications. It can be used to trace branch functions (INPUT, EXECUTE, CALL and RETURN instruction), memory allocations (subsequently using jfatty to look for memory leaks), and general profiling activity.

Invoking Profiling

The basic way to invoke the functionality is through the JDIAG environment variable. Below is a quick example run from the UNIX shell:

   % export JDIAG=branch=on:output=filename.out
   % MYPROGRAM

In this example,

• Two commands are specified and a colon (there can be any number of commands delimited) delimits them.
• branch=on means to turn on the tracing of branch instructions and write the trace output to the filename.out file.

It is also possible to dynamically run these commands against running programs. The same example as above but applied dynamically to port 23:

% jprof 23 branch=on:output=filename.out

You can obtain a short help screen as a quick reference reminder by the following:

 % JDIAG=help WHO
JDIAG=option{:option{:option ...}}
option can be one of ...
        profile={off|short|long|user|jcover}
        output={stdout|stderr|tmp|filename{,refresh_mins}
        memory={off|on|verify}
        branch={off|on}
        help
1 greg

Although the JDIAG environment variable name is case sensitive, the commands available in its value are not. For example, profile=ON is same as ProFILE=On.

The following table shows the available commands in JDIAG environmental variable.

Command	Description
profile=off	Turns off the general profiling tools
profile=short	Turns on the short form of profiling
profile=long	Turns on the long form of profiling
jprofile=user	Turns on the user-profiling output
profile=jcover	Turns on the form of profiling required for jcover
output=stdout	All the trace logs gets displayed to stdout
output=stderr	All the trace logs gets displayed to stderr
output=tmp{,nn}	The trace logs are written to $JBASICRELEASEDIR/tmp/jprof_nn, where nn is the process ID. You can optionally specify a cycle time in minutes. If the cycle time is specified, then 5 files are created with the suffixes _0 through _4 and the output logs will cycle through all 5 files in intervals of nn minutes.
output=filename{,nn}	The trace logs are written to the filename file, which can be any valid operating system file name, or even device name. Again, the optional cycle time can be used to create 5 files.
memory=off	Turns off all the traces of memory allocations
memory=on	Turns on the trace of memory allocations
memory=verify	Turns on the verification of memory allocations, over-runs, under-run memory allocations, duplicate released spaces, etc.  This can only be executed by using the JDIAG environment variable and cannot be set dynamically.
branch=off	Turns off all the branch traces
branch=on	Turns on the trace of branch instructions such as INPUT , CALL, RETURN and EXECUTE/PERFORM
help	Displays the short help messages.

As an example, assume that a program is running and gradually consuming more and more memory. You want to investigate the point of memory leakage.

1. Find the port number from where it is running.

   jsh --> WHERE
    Port   Device     Account      PID      Command                                                          
    0      6          greg         10941    MYPROG                                                            
   *1      8          greg         10949    WHERE
   

2. Start dynamically tracing the memory allocations.

   jsh->jprof 0 memory=on:output=MYPROG.output
   Message sent successfully to port 0
   

   The above command could take up to 60 seconds to invoke. Run MYPROG for 3 to 4 minutes to accumulate some statistics. The MYPROG.file output will increase in size as the trace begins.

3. Stop the trace

   jsh->jprof 0 memory=off
   Message sent successfully to port 0
   Wait 60 seconds to take effect
   

4. Run the jfatty command against the created file.

   jsh->jfatty MYPROG.output
   Remaining: 00005785: 100 bytes at 0x08115108 at test9C.c,6(test9.b,6)
   Remaining: 00005795: 100 bytes at 0x08115148 at test9C.c,6(test9.b,6)
   Remaining: 00005805: 100 bytes at 0x08115188 at test9C.c,6(test9.b,6)
   

   You can see where the memory is leaking.

   This is an example of hot-spot user profiling, the idea of which is that you place some function calls in either your jBASE BASIC code or your C code and let the profiling tools measure the CPU used between these calls. You call the JBASEUserProfile(n) function, where n is an integer between 0 and 10. A value of 0 means profiling ticks are discarded. A value of 1 through 10 means each CPU clock tick is stored in a 10 element array so you can ascertain how many CPU ticks arrived for that period.

Consider the following jBASE BASIC code example.

    INCLUDE JBASIC.h
    OPEN "FB1" TO DSCB ELSE DEBUG
    S1 = SYSTEM(12)
    FOR I = 1 TO 100000
        JBASEUserProfile(1)
        READU rec FROM DSCB,"x" ELSE NULL
        JBASEUserProfile(2)
        RELEASE
        JBASEUserProfile(0)
    NEXT I
    S2 = SYSTEM(12)
    PRINT "ELAPSED = ":(S2-S1)/1000

Compile normally with BASIC and CATALOG, or use the jcompile command.

When it is run, set the JDIAG variable as follows (assuming UNIX):

JDIAG=profile=user PROGRAMNAME
ELAPSED = 3.66
PROFILE:User Profile 1 , 30 ticks 83.33 %
PROFILE:User Profile 2 , 5 ticks 13.89 %

The output shows you that 83.33% of the CPU time is spent between the JBASEUserProfile(1) and JBASEUserProfile(2) function calls, and that 18.39% of the CPU time is spent between the JBASEUserProfile(2) and the JBASEUserProfile(0) function calls, thus proving that the RELEASE statement is consuming large amounts of CPU.

The function calls can equally be used in C code. To ensure more accuracy, the program should be run for at least a few seconds in order to accumulate as many CPU ticks as possible. Anything less than a second will increase the margin of error.

In particular, developers might like to notice the hot-spot user defined profiling which allows C code to be modified and easy verification of where CPU time is being spent within a function.

Simply add checkpoints into your jBASE BASIC or C code. At the end of the test program, it tells you how many ticks and what percentage of CPU was spent between these checkpoints. For example, there is a big JediOpen function that takes a huge amount of CPU, but where inside the JediOpen() does it take the most memory? Using the profiler, in this example allows you to identify that it is not JediOpen, but rather JediClose, which consumes more memory.