jprof

The jBASE profiling tools jprof enables developers to analyze applications to determine potential bottlenecks or trouble spots within the application code.

By default, no profiling is done in the program. Programs do not have to be compiled in any special manner to enable profiling for that program. All that is required is that the programs were not compiled with optimization, as this discards the debug information which is required for profiling.

The mechanism works by receiving a signal at every clock tick and keeping note of where the program was when the signal arrived. Thus, for the profiling to be accurate, the application must be run for a relatively long time. It will not show particularly good results if, for example, a program executes in less than a second. Several minutes or longer is preferred.

Currently profiling is available only with jBASE on Unix (including Linux) platforms.

ENABLING PROFILING

Profiling can either be enabled using the -JP option, which only profiles the root process, or via the JBCPROFILE environment variable, which profiles the root process as well as all EXECUTEd processes.

MAINPROG -JP

This command generates a profiling file called jprof_n in the current directory where where n is the port number. Only MAINPROG and any CALLed subroutines are profiled, any EXECUTEd programs will not be profiled. However, if the CPU time spent executing the actual EXECUTE statement is significant, that line will be included in the profiling statistics. When the application stops or chains to another program profiling is terminated.

JBCPROFILE=1
MAINPROG

This command generates a different profiling file for each process executed in the form jprof_pid_n, where pid is the process id and n is an incrementing number starting at 0.

The profiling file generated will only contain information about user CPU time. The time spent in system calls, file I/O, and lines which do not accumulate more than a clock tick are not included in the profiling statistics.

PROFILE REPORTING

The jprof command is used to provide profile analysis of the jprof files generated by a program executed with the -JP option.

Called as:
jprof -kfilename {jprof{_nnn}}
jprof -a {jprof{_nnn}}
jprof -o {-v} {jprof{_nnn}}
jprof -s {jprof{_nnn}}
jprof {-n{-u}} {-i} {-fFilename}} {jprof{_nnn}}

EXAMPLE OF PROFILING

Imagine the source "test1.b" below has been edited into file BP, where BP is a directory. Notice the INCLUDE of another source file "test2.b".

OPEN "fb1" TO DSCB ELSE STOP 201,"fb1"
PRINT "Phase 1 -- start"
S1 = SYSTEM(9)
FOR Id = 1 TO 100
    Rec = ""
    FOR I = 1 TO 100
        Line = ""
        FOR J = 1 TO 20
            Line := CHAR(SEQ("A")+RND(26))
        NEXT J
        Rec = Line
    NEXT I
    WRITE Rec ON DSCB,Id
NEXT Id
PRINT "Phase 1 -- end, CPU = ":SYSTEM(9)-S1
INCLUDE test2.b
PRINT C1:" records in file fb1"
PRINT "End"

The program can be created normally with the following command:

cd BP
jbc test1.b -o ../test1
cd ..

or it can be created with BASIC and CATALOG:

BASIC BP test1.b
CATALOG BP test1.b

By default, when the program is run, no profiling will take place. Now run the program with the -JP switch to create a file "jprof":

test1 -JP

We can now examine the profile file with the "jprof" command, using the -f option to generate optional source code listings from the file BP.

jprof -f BP jprof

PROFILE REPORT

Profile of program test1 from profile jprof Page 1

Source Line Ticks % Source

test2.b 8 166 32.93 READ Rec FROM DSCB,Key EL
test1.b 9 160 31.74 Line := CHAR(SEQ("A")+RND(
test1.b 11 128 25.39 Rec = Line
test2.b 7 28 5.55 WHILE READNEXT Key DO
test1.b 10 9 1.78 NEXT J
test2.b 9 5 0.99 C1++
test1.b 13 3 0.59 WRITE Rec ON DSCB,Id
test2.b 5 2 0.39 SELECT DSCB
test1.b 7 2 0.39 Line = "
test2.b 10 1 0.19 REPEAT

The -i option would sort the output with incrementing Ticks counts. The -n option would additionally sort it by file name, so the "test1.b" entries will be displayed separately to the "test2.b" entries.

Tools