As part of a debugging a problem I collected some traces. One was over 22 million lines of code! How do you extract information from it?

My trace file was trace.txt and I was looking for entries with java/lang/Object in them.

How big is the field?

The command (wc – lower case l)

wc -l trace.txt

gave me

22662732 trace.txt

22.6 million lines of output

Which part of the field?

grep -n java/lang/Object trace.txt |less

The -n option numbers the source lines.

The grep command gave me output starting with

601428:13:39:41.475442621 0x000000002174c200 j9vm.351 Entry >loader 0x0 class java/lang/Object attemptDynamicClassLoad entry

The first number is the position in the file, 601428.

Searching for “exit” (/exit) gave me

904914:13:39:44.830209269 0x000000002174c200 j9vm.319

line number 904919 in the file.

Extract some of the records

I want to ignore the first 601428-1 lines – then take up to and including line 904914 is a line count of 303486.

tail -n +601428 trace.txt |head -n 303487 |less -N

The plus sign in tail -n +… says -ignore the given number of lines.

This extracts the lines of interest and displays them with line numbers ( -N option). You can use >file1 to pipe it into a file, and then use less -N file.

I then iterated, now searching for j9shr – the Java Share Classes component, until I found the couple of interesting lines.

Extract data from a record.

You can extract field, or substrings using awk. For example piping data into

awk '{print substr($0,1,100)}'

Will display only the first 100 characters in a line.

awk '{print substr($0,7,6 )    substr($0,39,140)}'

Displays part of the time stamp – start column 7 for 6 characters, and from column 39 to 140.

You can also use cut to cut give specific fields, or field ranges, or column ranges. For example

cut --fields 1,3-5 -d " "
cut --bytes 1-8,60-100 

Where -d is the delimiter.

Clever stuff

The Java trace formatting gives you the option to indent the descriptions, if function p calls function q, function q is indented by 2 additional characters.

I used this, and a bit of Python code to calculate how long each request was active for and display this on the “exit” line of the function. I also saved how many times a function was used, and total time in the function.

The results were interesting – what I thought would be “slow” functions, were actually not slow.