Wrong logged time

[antonshkurenko]

Before using Hugo I used my own util class with such methods (same for methods, that return void):

public static <T> T howLong(String methodName, Method<T> command) {
    try {
      final long startTime = System.currentTimeMillis();
      final T result = command.execute();
      Timber.d("%s executed in %dms, thread: %s", methodName, System.currentTimeMillis() - startTime, Thread.currentThread().getName());
      return result;
    } catch (Exception e) {
      throw new RuntimeException(e);
    }
  }

Im trying to write gif encoder from scratch, and I log almost everything. I noticed, that all execution is pretty long, but one method (that should be the longest) is not long at all, I tried to log every other method, and finally I use my old util to log time and what I got:

V/AmazingGifEncoder: ⇠ map [1065ms] = [0x36, 0x36, 0x36, 0x36, 0x36, 0x36, 0x36, 0x36...
D/TimeUtils: Mapping pixels executed in 6745ms, thread: RxComputationThreadPool-1

At the same moment total execution time seems to be calculated correctly:

V/AmazingGifEncoder: ⇠ addFrame [7213ms]
D/TimeUtils: Adding frame executed in 7215ms, thread: RxComputationThreadPool-1

[JakeWharton]

Huh, strange. We're certainly not doing anything special with the calculation: https://github.com/JakeWharton/hugo/blob/63647a8f690eb38321f67ca196184d3a997ae112/hugo-runtime/src/main/java/hugo/weaving/internal/Hugo.java#L46-L49. I'm hesitant to think the overhead of the AOP methods added 5 seconds of execution time as well...

[antonshkurenko]

Problem is, even if I comment my logging, I still see very short time, shown by hugo, but I watch this in real time and I see that this process takes much more (also if I look at time in the logcat I see bigger time difference). In every other situation it logs time correctly.

final byte[] mappedPixels = /*TimeUtils.howLong("Mapping pixels", () -> */
        map(pixels, mPalette)/*)*/;

[antonshkurenko]

Here you can see execution time by hugo and logcat time

11:07:54.055 V/AmazingGifEncoder: ⇢ map(pixels=[-15720432, -15720432, -15720432, -15720432, -15721456, -15720432, -15194088, -15193055, -15720432, -15720432, -15719400...
11:07:57.500 V/AmazingGifEncoder: ⇠ map [23ms] = [0x06, 0x06, 0x06, 0x06, 0x06, 0x06, 0x06, 0x07...

[yhartanto]

Could you please share some of the code that is not recorded correctly?

[antonshkurenko]

It produces bad quality, but still it works as gif encoder.

Example usage:

final ByteArrayOutputStream bos = new ByteArrayOutputStream();
final AmazingGifEncoder encoder = new AmazingGifEncoder();
encoder.start(bos, true);

final int length = bitmapNames.size();
for (int i = 0; i < length; i++) {
  final String bitmapName = bitmapNames.get(i);
  final Bitmap bitmap = howLong("Retrieving bitmap", () -> BitmapUtils.retrieve(bitmapName));
  if (bitmap == null) {
    continue;
  }
  howLongVoid("Adding frame", () -> encoder.addFrame(bitmap, mDelay / 10));
}

encoder.finish();
FileUtils.store(bos.toByteArray(), path);

AmazingGifEncoder.java.zip

[antonshkurenko]

Ok, I've spent tons of hours trying to optimize my algorithm, but also I found an answer to this.

I have only thoughts, why this problem exists, but I can show you:

Hugo
Time logged only with hugo, another time was logging this way:

long startTime = System.currentTimeMillis();
final int[][][] colorMap = createPalette(pixels, palette);
Timber.d("Creating palette in %d", (System.currentTimeMillis() - startTime));

V/HistogramGifEncoder: ⇢ addFrame(im=android.graphics.Bitmap@41801078, delay=6) [Thread:"RxComputationThreadPool-2"]
V/HistogramGifEncoder: ⇢ createPalette(pixels=[-8083762, -8083762, -8083762, -8084786, -8085818, -8676675, -8677707, -8677707, -8677707 ...
V/HistogramGifEncoder: ⇠ createPalette [52ms] = [[[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0...
D/HistogramGifEncoder: Creating palette in 645
V/HistogramGifEncoder: ⇢ map(pixels=[-8083762, -8083762, -8083762, -8084786, -8085818, -8676675, -8677707, -8677707, -8677707, -8677707, -8678731, -8679763, -8679763, -8679763, -8680787, -8681819, -9204068, -9204068, -9205092, -9205092, -9206116, -9206116, -9206124, -9206124, -9206124, -9206124, -9207148 ...
V/HistogramGifEncoder: ⇠ map [5ms] = [0x3B, 0x3B, 0x3B, 0x3B, 0x42, 0x42, 0x4A, 0x4A, 0x4A, 0x4A, 0x45, 0x45, 0x45, 0x45, 0x45, 0x87, 0x35, 0x35, 0x35 ...
D/HistogramGifEncoder: Mapping pixels in 5121
V/HistogramGifEncoder: ⇠ addFrame [5790ms]

Also I deleted tons of lines:

I/dalvikvm-heap: Grow heap (frag case) to 13.540MB for 2239514-byte allocation

TimeUtils.java
Time logged only with TimeUtils, another time was logging this way:

long startTime = System.currentTimeMillis();
final int[][][] colorMap =
    TimeUtils.howLong("Create palette", () -> createPalette(pixels, palette));
Timber.d("Creating palette in %d", (System.currentTimeMillis() - startTime));

V/HistogramGifEncoder: ⇢ addFrame(im=android.graphics.Bitmap@41a43c18, delay=6) [Thread:"RxComputationThreadPool-1"]
D/TimeUtils: Create palette executed in 258ms, thread: RxComputationThreadPool-1
D/HistogramGifEncoder: Creating palette in 259
D/TimeUtils: Mapping pixels executed in 5ms, thread: RxComputationThreadPool-1
D/HistogramGifEncoder: Mapping pixels in 6
V/HistogramGifEncoder: ⇠ addFrame [290ms]

Nothing
Time logged only this way:

long startTime = System.currentTimeMillis();
final int[][][] colorMap = createPalette(pixels, palette);
Timber.d("Creating palette in %d", (System.currentTimeMillis() - startTime));

V/HistogramGifEncoder: ⇢ addFrame(im=android.graphics.Bitmap@41bc1ec0, delay=6) [Thread:"RxComputationThreadPool-1"]
D/HistogramGifEncoder: Creating palette in 230
D/HistogramGifEncoder: Mapping pixels in 5
V/HistogramGifEncoder: ⇠ addFrame [256ms]

Seems like big arrays (this array is a bitmap 288x288, palette is int [256], colorMap is array int [32][64][32], mapped pixels is array byte [288 * 288], pixels array is int [288 * 288]) makes hugo slower (returned objects, arguments).

[JakeWharton]

Presumably this time is spent in the code to actually create the log messages. From what I remember, we loop over arrays, so if you're passing a large byte[] we might not be limiting the times it loops.