Today I got confused by the results of Visual VM profiling I got.
I have the following simple Java method:
public class Encoder {
...
private BitString encode(InputStream in, Map<Character, BitString> table)
throws IOException {
BufferedReader reader = new BufferedReader(new InputStreamReader(in));
BitString result = new BitString();
int i;
while ((i = reader.read()) != -1) {
char ch = (char) i;
BitString string = table.get(ch);
result = result.append(string);
}
return result;
}
}
This method reads characters from a stream, one at a time. For each character it looks up it's bit-string representation and it joins these bit-strings to represent the whole stream.
A BitString is a custom data structure that represents a sequence of bits using an underlying byte array.
The method performs very poorly. The problem lies with BitString#append - that method creates a new byte array, copies the bits from both input BitStrings and returns it as a new BitString instance.
public BitString append(BitString other) {
BitString result = new BitString(size + other.size);
int pos = 0;
for (byte b : this) {
result.set(pos, b);
pos++;
}
for (byte b : other) {
result.set(pos, b);
pos++;
}
return result;
}
However, when I tried to use VisualVM to verify what's happening, here's what I got:
I have very little experience with Visual VM and profiling in general. To my understanding, this looks as if the problem lied somewhere in encode method itself, not in append.
To be sure, I surrounded the whole encode method and the append call with custom time measuring, like this:
public class Encoder {
private BitString encode(InputStream in, Map<Character, BitString> table)
throws IOException {
>> long startTime = System.currentTimeMillis();
>> long appendDuration = 0;
BufferedReader reader = new BufferedReader(new InputStreamReader(in));
BitString result = new BitString();
int i;
>> long count = 0;
while ((i = reader.read()) != -1) {
char ch = (char) i;
BitString string = table.get(ch);
>> long appendStartTime = System.currentTimeMillis();
result = result.append(string);
>> long appendEndTime = System.currentTimeMillis();
>> appendDuration += appendEndTime - appendStartTime;
>> count++;
>> if (count % 1000 == 0) {
>> log.info(">>> CHARACTERS PROCESSED: " + count);
>> long endTime = System.currentTimeMillis();
>> log.info(">>> TOTAL ENCODE DURATION: " + (endTime - startTime) + " ms");
>> log.info(">>> TOTAL APPEND DURATION: " + appendDuration + " ms");
>> }
}
return result;
}
}
And I got the following results:
CHARACTERS PROCESSED: 102000
TOTAL ENCODE DURATION: 188276 ms
APPEND CALL DURATION: 188179 ms
This seems in contradiction with the results from Visual VM.
What am I missing?
