src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java - bazel - Git at Google

 // Copyright 2015 The Bazel Authors. All rights reserved.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
 // You may obtain a copy of the License at
 //
 //    http://www.apache.org/licenses/LICENSE-2.0
 //
 // Unless required by applicable law or agreed to in writing, software
 // distributed under the License is distributed on an "AS IS" BASIS,
 // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 // See the License for the specific language governing permissions and
 // limitations under the License.
 package com.google.devtools.build.lib.profiler;

 import static com.google.common.truth.Truth.assertThat;
 import static java.nio.charset.StandardCharsets.ISO_8859_1;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertFalse;
 import static org.junit.Assert.assertTrue;
 import static org.junit.Assert.fail;

 import com.google.devtools.build.lib.profiler.Profiler.ProfiledTaskKinds;
 import com.google.devtools.build.lib.testutil.FoundationTestCase;
 import com.google.devtools.build.lib.testutil.Suite;
 import com.google.devtools.build.lib.testutil.TestSpec;
 import com.google.devtools.build.lib.util.BlazeClock;
 import com.google.devtools.build.lib.util.Clock;
 import com.google.devtools.build.lib.vfs.FileSystemUtils;
 import com.google.devtools.build.lib.vfs.Path;

 import org.junit.Before;
 import org.junit.Test;
 import org.junit.runner.RunWith;
 import org.junit.runners.JUnit4;

 import java.io.InputStream;
 import java.io.OutputStream;
 import java.util.Arrays;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.zip.Deflater;
 import java.util.zip.DeflaterOutputStream;
 import java.util.zip.Inflater;
 import java.util.zip.InflaterInputStream;

 /**
  * Unit tests for the profiler.
  */
 @TestSpec(size = Suite.MEDIUM_TESTS) // testConcurrentProfiling takes ~700ms, testProfiler 100ms.
 @RunWith(JUnit4.class)
 public class ProfilerTest extends FoundationTestCase {

   private Path cacheDir;
   private Profiler profiler = Profiler.instance();

   @Before
   public final void createCacheDirectory() throws Exception {
     cacheDir = scratch.dir("/tmp");
   }

   @Test
   public void testProfilerActivation() throws Exception {
     Path cacheFile = cacheDir.getRelative("profile1.dat");
     assertFalse(profiler.isActive());
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", false,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     assertTrue(profiler.isActive());

     profiler.stop();
     assertFalse(profiler.isActive());
   }

   @Test
   public void testTaskDetails() throws Exception {
     Path cacheFile = cacheDir.getRelative("profile1.dat");
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", false,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     profiler.startTask(ProfilerTask.ACTION, "action task");
     profiler.logEvent(ProfilerTask.TEST, "event");
     profiler.completeTask(ProfilerTask.ACTION);
     profiler.stop();
     ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
     info.calculateStats();

     ProfileInfo.Task task = info.allTasksById.get(0);
     assertEquals(1, task.id);
     assertEquals(ProfilerTask.ACTION, task.type);
     assertEquals("action task", task.getDescription());

     task = info.allTasksById.get(1);
     assertEquals(2, task.id);
     assertEquals(ProfilerTask.TEST, task.type);
     assertEquals("event", task.getDescription());
   }

   @Test
   public void testProfiler() throws Exception {
     Path cacheFile = cacheDir.getRelative("profile1.dat");
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", false,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     profiler.logSimpleTask(getTestClock().nanoTime(),
                            ProfilerTask.PHASE, "profiler start");
     profiler.startTask(ProfilerTask.ACTION, "complex task");
     profiler.logEvent(ProfilerTask.PHASE, "event1");
     profiler.startTask(ProfilerTask.ACTION_CHECK, "complex subtask");
     // next task takes less than 10 ms and should be only aggregated
     profiler.logSimpleTask(getTestClock().nanoTime(),
                            ProfilerTask.VFS_STAT, "stat1");
     long startTime = getTestClock().nanoTime();
     Thread.sleep(20);
     // this one will take at least 20 ms and should be present
     profiler.logSimpleTask(startTime, ProfilerTask.VFS_STAT, "stat2");
     profiler.completeTask(ProfilerTask.ACTION_CHECK);
     profiler.completeTask(ProfilerTask.ACTION);
     profiler.stop();
     // all other calls to profiler should be ignored
     profiler.logEvent(ProfilerTask.PHASE, "should be ignored");
     // normally this would cause an exception but it is ignored since profiler
     // is disabled
     profiler.completeTask(ProfilerTask.ACTION_EXECUTE);

     ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
     info.calculateStats();
     assertThat(info.allTasksById).hasSize(6); // only 5 tasks + finalization should be recorded

     ProfileInfo.Task task = info.allTasksById.get(0);
     assertTrue(task.stats.isEmpty());

     task = info.allTasksById.get(1);
     int count = 0;
     for (ProfileInfo.AggregateAttr attr : task.getStatAttrArray()) {
       if (attr != null) {
         count++;
       }
     }
     assertEquals(count, 2); // only children are GENERIC and ACTION_CHECK
     assertEquals(task.aggregatedStats.toArray().length, ProfilerTask.TASK_COUNT);
     assertEquals(task.aggregatedStats.getAttr(ProfilerTask.VFS_STAT).count, 2);

     task = info.allTasksById.get(2);
     assertThat(task.durationNanos).isEqualTo(0);

     task = info.allTasksById.get(3);
     assertEquals(task.stats.getAttr(ProfilerTask.VFS_STAT).count, 2);
     assertEquals(task.subtasks.length, 1);
     assertEquals(task.subtasks[0].getDescription(), "stat2");
     // assert that startTime grows with id
     long time = -1;
     for (ProfileInfo.Task t : info.allTasksById) {
       assertTrue(t.startTime >= time);
       time = t.startTime;
     }
   }

   @Test
   public void testProfilerRecordingAllEvents() throws Exception {
     Path cacheFile = cacheDir.getRelative("profile1.dat");
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", true,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     profiler.startTask(ProfilerTask.ACTION, "action task");
     // Next task takes less than 10 ms but should be recorded anyway.
     profiler.logSimpleTask(getTestClock().nanoTime(), ProfilerTask.VFS_STAT, "stat1");
     profiler.completeTask(ProfilerTask.ACTION);
     profiler.stop();
     ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
     info.calculateStats();
     assertThat(info.allTasksById).hasSize(3); // 2 tasks + finalization should be recorded

     ProfileInfo.Task task = info.allTasksById.get(1);
     assertEquals(ProfilerTask.VFS_STAT, task.type);

     // Check that task would have been dropped if profiler was not configured to record everything.
     assertThat(task.durationNanos).isLessThan(ProfilerTask.VFS_STAT.minDuration);
   }

   @Test
   public void testProfilerRecordingOnlySlowestEvents() throws Exception {
     Path profileData = cacheDir.getRelative("foo");

     profiler.start(ProfiledTaskKinds.SLOWEST, profileData.getOutputStream(), "test", true,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");
     profiler.logSimpleTask(20000, 30000, ProfilerTask.REMOTE_EXECUTION, "remote execution");

     assertTrue(profiler.isProfiling(ProfilerTask.VFS_STAT));
     assertFalse(profiler.isProfiling(ProfilerTask.REMOTE_EXECUTION));

     profiler.stop();

     ProfileInfo info = ProfileInfo.loadProfile(profileData);
     info.calculateStats();
     assertThat(info.allTasksById).hasSize(1); // only VFS_STAT task should be recorded

     ProfileInfo.Task task = info.allTasksById.get(0);
     assertEquals(ProfilerTask.VFS_STAT, task.type);
   }

   @Test
   public void testProfilerRecordsNothing() throws Exception {
     Path profileData = cacheDir.getRelative("foo");

     profiler.start(ProfiledTaskKinds.NONE, profileData.getOutputStream(), "test", true,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");

     assertTrue(ProfilerTask.VFS_STAT.collectsSlowestInstances());
     assertFalse(profiler.isProfiling(ProfilerTask.VFS_STAT));

     profiler.stop();

     ProfileInfo info = ProfileInfo.loadProfile(profileData);
     info.calculateStats();
     assertThat(info.allTasksById).isEmpty();
   }

   @Test
   public void testInconsistentCompleteTask() throws Exception {
     Path cacheFile = cacheDir.getRelative("profile2.dat");
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(),
         "task stack inconsistency test", false,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     profiler.startTask(ProfilerTask.PHASE, "some task");
     try {
       profiler.completeTask(ProfilerTask.ACTION);
       fail();
     } catch (IllegalStateException e) {
       // this is expected
     }
     profiler.stop();
   }

   @Test
   public void testConcurrentProfiling() throws Exception {
     Path cacheFile = cacheDir.getRelative("profile3.dat");
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "concurrent test", false,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());

     long id = Thread.currentThread().getId();
     Thread thread1 = new Thread() {
       @Override public void run() {
         for (int i = 0; i < 10000; i++) {
           Profiler.instance().logEvent(ProfilerTask.TEST, "thread1");
         }
       }
     };
     long id1 = thread1.getId();
     Thread thread2 = new Thread() {
       @Override public void run() {
         for (int i = 0; i < 10000; i++) {
           Profiler.instance().logEvent(ProfilerTask.TEST, "thread2");
         }
       }
     };
     long id2 = thread2.getId();

     profiler.startTask(ProfilerTask.PHASE, "main task");
     profiler.logEvent(ProfilerTask.TEST, "starting threads");
     thread1.start();
     thread2.start();
     thread2.join();
     thread1.join();
     profiler.logEvent(ProfilerTask.TEST, "joined");
     profiler.completeTask(ProfilerTask.PHASE);
     profiler.stop();

     ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
     info.calculateStats();
     info.analyzeRelationships();
     assertEquals(info.allTasksById.size(), 4 + 10000 + 10000); // total number of tasks
     assertEquals(info.tasksByThread.size(), 3); // total number of threads
     // while main thread had 3 tasks, 2 of them were nested, so tasksByThread
     // would contain only one "main task" task
     assertEquals(info.tasksByThread.get(id).length, 2);
     ProfileInfo.Task mainTask = info.tasksByThread.get(id)[0];
     assertEquals(mainTask.getDescription(), "main task");
     assertEquals(mainTask.subtasks.length, 2);
     // other threads had 10000 independent recorded tasks each
     assertEquals(info.tasksByThread.get(id1).length, 10000);
     assertEquals(info.tasksByThread.get(id2).length, 10000);
     int startId = mainTask.subtasks[0].id; // id of "starting threads"
     int endId = mainTask.subtasks[1].id; // id of "joining"
     assertTrue(startId < info.tasksByThread.get(id1)[0].id);
     assertTrue(startId < info.tasksByThread.get(id2)[0].id);
     assertTrue(endId > info.tasksByThread.get(id1)[9999].id);
     assertTrue(endId > info.tasksByThread.get(id2)[9999].id);
   }

   @Test
   public void testPhaseTasks() throws Exception {
     Path cacheFile = cacheDir.getRelative("profile4.dat");
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "phase test", false,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     Thread thread1 = new Thread() {
       @Override public void run() {
         for (int i = 0; i < 100; i++) {
           Profiler.instance().logEvent(ProfilerTask.TEST, "thread1");
         }
       }
     };
     profiler.markPhase(ProfilePhase.INIT); // Empty phase.
     profiler.markPhase(ProfilePhase.LOAD);
     thread1.start();
     thread1.join();
     Thread.sleep(1);
     profiler.markPhase(ProfilePhase.ANALYZE);
     Thread thread2 = new Thread() {
       @Override public void run() {
         profiler.startTask(ProfilerTask.TEST, "complex task");
         for (int i = 0; i < 100; i++) {
           Profiler.instance().logEvent(ProfilerTask.TEST, "thread2a");
         }
         profiler.completeTask(ProfilerTask.TEST);
         profiler.markPhase(ProfilePhase.EXECUTE);
         for (int i = 0; i < 100; i++) {
           Profiler.instance().logEvent(ProfilerTask.TEST, "thread2b");
         }
       }
     };
     thread2.start();
     thread2.join();
     profiler.logEvent(ProfilerTask.TEST, "last task");
     Thread.sleep(1);
     profiler.stop();

     ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
     info.calculateStats();
     info.analyzeRelationships();
     // number of tasks: INIT(1) + LOAD(1) + Thread1.TEST(100) + ANALYZE(1)
     // + Thread2a.TEST(100) + TEST(1) + EXECUTE(1) + Thread2b.TEST(100) + TEST(1) + INFO(1)
     assertThat(info.allTasksById).hasSize(1 + 1 + 100 + 1 + 100 + 1 + 1 + 100 + 1 + 1);
     assertThat(info.tasksByThread).hasSize(3); // total number of threads
     // Phase0 contains only itself
     ProfileInfo.Task p0 = info.getPhaseTask(ProfilePhase.INIT);
     assertThat(info.getTasksForPhase(p0)).hasSize(1);
     // Phase1 contains itself and 100 TEST "thread1" tasks
     ProfileInfo.Task p1 = info.getPhaseTask(ProfilePhase.LOAD);
     assertThat(info.getTasksForPhase(p1)).hasSize(101);
     // Phase2 contains itself and 1 "complex task"
     ProfileInfo.Task p2 = info.getPhaseTask(ProfilePhase.ANALYZE);
     assertThat(info.getTasksForPhase(p2)).hasSize(2);
     // Phase3 contains itself, 100 TEST "thread2b" tasks and "last task"
     ProfileInfo.Task p3 = info.getPhaseTask(ProfilePhase.EXECUTE);
     assertThat(info.getTasksForPhase(p3)).hasSize(103);
   }

   @Test
   public void testCorruptedFile() throws Exception {
     Path cacheFile = cacheDir.getRelative("profile5.dat");
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "phase test", false,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     for (int i = 0; i < 100; i++) {
       profiler.startTask(ProfilerTask.TEST, "outer task " + i);
       profiler.logEvent(ProfilerTask.TEST, "inner task " + i);
       profiler.completeTask(ProfilerTask.TEST);
     }
     profiler.stop();

     ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
     info.calculateStats();
     assertFalse(info.isCorruptedOrIncomplete());

     Path corruptedFile = cacheDir.getRelative("profile5bad.dat");
     FileSystemUtils.writeContent(
         corruptedFile, Arrays.copyOf(FileSystemUtils.readContent(cacheFile), 2000));
     info = ProfileInfo.loadProfile(corruptedFile);
     info.calculateStats();
     assertTrue(info.isCorruptedOrIncomplete());
     // Since root tasks will appear after nested tasks in the profile file and
     // we have exactly one nested task for each root task, then following will be
     // always true for our corrupted file:
     // 0 <= number_of_all_tasks - 2*number_of_root_tasks <= 1
     assertEquals(info.rootTasksById.size(), info.allTasksById.size() / 2);
   }

   @Test
   public void testUnsupportedProfilerRecord() throws Exception {
     Path dataFile = cacheDir.getRelative("profile5.dat");
     profiler.start(ProfiledTaskKinds.ALL, dataFile.getOutputStream(), "phase test", false,
         BlazeClock.instance(), BlazeClock.instance().nanoTime());
     profiler.startTask(ProfilerTask.TEST, "outer task");
     profiler.logEvent(ProfilerTask.EXCEPTION, "inner task");
     profiler.completeTask(ProfilerTask.TEST);
     profiler.startTask(ProfilerTask.SCANNER, "outer task 2");
     profiler.logSimpleTask(Profiler.nanoTimeMaybe(), ProfilerTask.TEST, "inner task 2");
     profiler.completeTask(ProfilerTask.SCANNER);
     profiler.stop();

     // Validate our test profile.
     ProfileInfo info = ProfileInfo.loadProfile(dataFile);
     info.calculateStats();
     assertFalse(info.isCorruptedOrIncomplete());
     assertEquals(2, info.getStatsForType(ProfilerTask.TEST, info.rootTasksById).count);
     assertEquals(0, info.getStatsForType(ProfilerTask.UNKNOWN, info.rootTasksById).count);

     // Now replace "TEST" type with something unsupported - e.g. "XXXX".
     InputStream in = new InflaterInputStream(dataFile.getInputStream(), new Inflater(false), 65536);
     byte[] buffer = new byte[60000];
     int len = in.read(buffer);
     in.close();
     assertTrue(len < buffer.length); // Validate that file was completely decoded.
     String content = new String(buffer, ISO_8859_1);
     int infoIndex = content.indexOf("TEST");
     assertTrue(infoIndex > 0);
     content = content.substring(0, infoIndex) + "XXXX" + content.substring(infoIndex + 4);
     OutputStream out = new DeflaterOutputStream(dataFile.getOutputStream(),
         new Deflater(Deflater.BEST_SPEED, false), 65536);
     out.write(content.getBytes(ISO_8859_1));
     out.close();

     // Validate that XXXX records were classified as UNKNOWN.
     info = ProfileInfo.loadProfile(dataFile);
     info.calculateStats();
     assertFalse(info.isCorruptedOrIncomplete());
     assertEquals(0, info.getStatsForType(ProfilerTask.TEST, info.rootTasksById).count);
     assertEquals(1, info.getStatsForType(ProfilerTask.SCANNER, info.rootTasksById).count);
     assertEquals(1, info.getStatsForType(ProfilerTask.EXCEPTION, info.rootTasksById).count);
     assertEquals(2, info.getStatsForType(ProfilerTask.UNKNOWN, info.rootTasksById).count);
   }

   @Test
   public void testResilenceToNonDecreasingNanoTimes() throws Exception {
     final long initialNanoTime = BlazeClock.instance().nanoTime();
     final AtomicInteger numNanoTimeCalls = new AtomicInteger(0);
     Clock badClock = new Clock() {
       @Override
       public long currentTimeMillis() {
         return BlazeClock.instance().currentTimeMillis();
       }

       @Override
       public long nanoTime() {
         return initialNanoTime - numNanoTimeCalls.addAndGet(1);
       }
     };
     Path cacheFile = cacheDir.getRelative("profile1.dat");
     profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(),
         "testResilenceToNonDecreasingNanoTimes", false, badClock, initialNanoTime);
     profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.TEST, "some task");
     profiler.stop();
   }

   private Clock getTestClock() {
     return BlazeClock.instance();
   }

 }
	// Copyright 2015 The Bazel Authors. All rights reserved.
	//
	// Licensed under the Apache License, Version 2.0 (the "License");
	// you may not use this file except in compliance with the License.
	// You may obtain a copy of the License at
	//
	// http://www.apache.org/licenses/LICENSE-2.0
	//
	// Unless required by applicable law or agreed to in writing, software
	// distributed under the License is distributed on an "AS IS" BASIS,
	// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
	// See the License for the specific language governing permissions and
	// limitations under the License.
	package com.google.devtools.build.lib.profiler;

	import static com.google.common.truth.Truth.assertThat;
	import static java.nio.charset.StandardCharsets.ISO_8859_1;
	import static org.junit.Assert.assertEquals;
	import static org.junit.Assert.assertFalse;
	import static org.junit.Assert.assertTrue;
	import static org.junit.Assert.fail;

	import com.google.devtools.build.lib.profiler.Profiler.ProfiledTaskKinds;
	import com.google.devtools.build.lib.testutil.FoundationTestCase;
	import com.google.devtools.build.lib.testutil.Suite;
	import com.google.devtools.build.lib.testutil.TestSpec;
	import com.google.devtools.build.lib.util.BlazeClock;
	import com.google.devtools.build.lib.util.Clock;
	import com.google.devtools.build.lib.vfs.FileSystemUtils;
	import com.google.devtools.build.lib.vfs.Path;

	import org.junit.Before;
	import org.junit.Test;
	import org.junit.runner.RunWith;
	import org.junit.runners.JUnit4;

	import java.io.InputStream;
	import java.io.OutputStream;
	import java.util.Arrays;
	import java.util.concurrent.atomic.AtomicInteger;
	import java.util.zip.Deflater;
	import java.util.zip.DeflaterOutputStream;
	import java.util.zip.Inflater;
	import java.util.zip.InflaterInputStream;

	/**
	* Unit tests for the profiler.
	*/
	@TestSpec(size = Suite.MEDIUM_TESTS) // testConcurrentProfiling takes ~700ms, testProfiler 100ms.
	@RunWith(JUnit4.class)
	public class ProfilerTest extends FoundationTestCase {

	private Path cacheDir;
	private Profiler profiler = Profiler.instance();

	@Before
	public final void createCacheDirectory() throws Exception {
	cacheDir = scratch.dir("/tmp");
	}

	@Test
	public void testProfilerActivation() throws Exception {
	Path cacheFile = cacheDir.getRelative("profile1.dat");
	assertFalse(profiler.isActive());
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", false,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	assertTrue(profiler.isActive());

	profiler.stop();
	assertFalse(profiler.isActive());
	}

	@Test
	public void testTaskDetails() throws Exception {
	Path cacheFile = cacheDir.getRelative("profile1.dat");
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", false,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	profiler.startTask(ProfilerTask.ACTION, "action task");
	profiler.logEvent(ProfilerTask.TEST, "event");
	profiler.completeTask(ProfilerTask.ACTION);
	profiler.stop();
	ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
	info.calculateStats();

	ProfileInfo.Task task = info.allTasksById.get(0);
	assertEquals(1, task.id);
	assertEquals(ProfilerTask.ACTION, task.type);
	assertEquals("action task", task.getDescription());

	task = info.allTasksById.get(1);
	assertEquals(2, task.id);
	assertEquals(ProfilerTask.TEST, task.type);
	assertEquals("event", task.getDescription());
	}

	@Test
	public void testProfiler() throws Exception {
	Path cacheFile = cacheDir.getRelative("profile1.dat");
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", false,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	profiler.logSimpleTask(getTestClock().nanoTime(),
	ProfilerTask.PHASE, "profiler start");
	profiler.startTask(ProfilerTask.ACTION, "complex task");
	profiler.logEvent(ProfilerTask.PHASE, "event1");
	profiler.startTask(ProfilerTask.ACTION_CHECK, "complex subtask");
	// next task takes less than 10 ms and should be only aggregated
	profiler.logSimpleTask(getTestClock().nanoTime(),
	ProfilerTask.VFS_STAT, "stat1");
	long startTime = getTestClock().nanoTime();
	Thread.sleep(20);
	// this one will take at least 20 ms and should be present
	profiler.logSimpleTask(startTime, ProfilerTask.VFS_STAT, "stat2");
	profiler.completeTask(ProfilerTask.ACTION_CHECK);
	profiler.completeTask(ProfilerTask.ACTION);
	profiler.stop();
	// all other calls to profiler should be ignored
	profiler.logEvent(ProfilerTask.PHASE, "should be ignored");
	// normally this would cause an exception but it is ignored since profiler
	// is disabled
	profiler.completeTask(ProfilerTask.ACTION_EXECUTE);

	ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
	info.calculateStats();
	assertThat(info.allTasksById).hasSize(6); // only 5 tasks + finalization should be recorded

	ProfileInfo.Task task = info.allTasksById.get(0);
	assertTrue(task.stats.isEmpty());

	task = info.allTasksById.get(1);
	int count = 0;
	for (ProfileInfo.AggregateAttr attr : task.getStatAttrArray()) {
	if (attr != null) {
	count++;
	}
	}
	assertEquals(count, 2); // only children are GENERIC and ACTION_CHECK
	assertEquals(task.aggregatedStats.toArray().length, ProfilerTask.TASK_COUNT);
	assertEquals(task.aggregatedStats.getAttr(ProfilerTask.VFS_STAT).count, 2);

	task = info.allTasksById.get(2);
	assertThat(task.durationNanos).isEqualTo(0);

	task = info.allTasksById.get(3);
	assertEquals(task.stats.getAttr(ProfilerTask.VFS_STAT).count, 2);
	assertEquals(task.subtasks.length, 1);
	assertEquals(task.subtasks[0].getDescription(), "stat2");
	// assert that startTime grows with id
	long time = -1;
	for (ProfileInfo.Task t : info.allTasksById) {
	assertTrue(t.startTime >= time);
	time = t.startTime;
	}
	}

	@Test
	public void testProfilerRecordingAllEvents() throws Exception {
	Path cacheFile = cacheDir.getRelative("profile1.dat");
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "basic test", true,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	profiler.startTask(ProfilerTask.ACTION, "action task");
	// Next task takes less than 10 ms but should be recorded anyway.
	profiler.logSimpleTask(getTestClock().nanoTime(), ProfilerTask.VFS_STAT, "stat1");
	profiler.completeTask(ProfilerTask.ACTION);
	profiler.stop();
	ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
	info.calculateStats();
	assertThat(info.allTasksById).hasSize(3); // 2 tasks + finalization should be recorded

	ProfileInfo.Task task = info.allTasksById.get(1);
	assertEquals(ProfilerTask.VFS_STAT, task.type);

	// Check that task would have been dropped if profiler was not configured to record everything.
	assertThat(task.durationNanos).isLessThan(ProfilerTask.VFS_STAT.minDuration);
	}

	@Test
	public void testProfilerRecordingOnlySlowestEvents() throws Exception {
	Path profileData = cacheDir.getRelative("foo");

	profiler.start(ProfiledTaskKinds.SLOWEST, profileData.getOutputStream(), "test", true,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");
	profiler.logSimpleTask(20000, 30000, ProfilerTask.REMOTE_EXECUTION, "remote execution");

	assertTrue(profiler.isProfiling(ProfilerTask.VFS_STAT));
	assertFalse(profiler.isProfiling(ProfilerTask.REMOTE_EXECUTION));

	profiler.stop();

	ProfileInfo info = ProfileInfo.loadProfile(profileData);
	info.calculateStats();
	assertThat(info.allTasksById).hasSize(1); // only VFS_STAT task should be recorded

	ProfileInfo.Task task = info.allTasksById.get(0);
	assertEquals(ProfilerTask.VFS_STAT, task.type);
	}

	@Test
	public void testProfilerRecordsNothing() throws Exception {
	Path profileData = cacheDir.getRelative("foo");

	profiler.start(ProfiledTaskKinds.NONE, profileData.getOutputStream(), "test", true,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");

	assertTrue(ProfilerTask.VFS_STAT.collectsSlowestInstances());
	assertFalse(profiler.isProfiling(ProfilerTask.VFS_STAT));

	profiler.stop();

	ProfileInfo info = ProfileInfo.loadProfile(profileData);
	info.calculateStats();
	assertThat(info.allTasksById).isEmpty();
	}

	@Test
	public void testInconsistentCompleteTask() throws Exception {
	Path cacheFile = cacheDir.getRelative("profile2.dat");
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(),
	"task stack inconsistency test", false,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	profiler.startTask(ProfilerTask.PHASE, "some task");
	try {
	profiler.completeTask(ProfilerTask.ACTION);
	fail();
	} catch (IllegalStateException e) {
	// this is expected
	}
	profiler.stop();
	}

	@Test
	public void testConcurrentProfiling() throws Exception {
	Path cacheFile = cacheDir.getRelative("profile3.dat");
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "concurrent test", false,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());

	long id = Thread.currentThread().getId();
	Thread thread1 = new Thread() {
	@Override public void run() {
	for (int i = 0; i < 10000; i++) {
	Profiler.instance().logEvent(ProfilerTask.TEST, "thread1");
	}
	}
	};
	long id1 = thread1.getId();
	Thread thread2 = new Thread() {
	@Override public void run() {
	for (int i = 0; i < 10000; i++) {
	Profiler.instance().logEvent(ProfilerTask.TEST, "thread2");
	}
	}
	};
	long id2 = thread2.getId();

	profiler.startTask(ProfilerTask.PHASE, "main task");
	profiler.logEvent(ProfilerTask.TEST, "starting threads");
	thread1.start();
	thread2.start();
	thread2.join();
	thread1.join();
	profiler.logEvent(ProfilerTask.TEST, "joined");
	profiler.completeTask(ProfilerTask.PHASE);
	profiler.stop();

	ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
	info.calculateStats();
	info.analyzeRelationships();
	assertEquals(info.allTasksById.size(), 4 + 10000 + 10000); // total number of tasks
	assertEquals(info.tasksByThread.size(), 3); // total number of threads
	// while main thread had 3 tasks, 2 of them were nested, so tasksByThread
	// would contain only one "main task" task
	assertEquals(info.tasksByThread.get(id).length, 2);
	ProfileInfo.Task mainTask = info.tasksByThread.get(id)[0];
	assertEquals(mainTask.getDescription(), "main task");
	assertEquals(mainTask.subtasks.length, 2);
	// other threads had 10000 independent recorded tasks each
	assertEquals(info.tasksByThread.get(id1).length, 10000);
	assertEquals(info.tasksByThread.get(id2).length, 10000);
	int startId = mainTask.subtasks[0].id; // id of "starting threads"
	int endId = mainTask.subtasks[1].id; // id of "joining"
	assertTrue(startId < info.tasksByThread.get(id1)[0].id);
	assertTrue(startId < info.tasksByThread.get(id2)[0].id);
	assertTrue(endId > info.tasksByThread.get(id1)[9999].id);
	assertTrue(endId > info.tasksByThread.get(id2)[9999].id);
	}

	@Test
	public void testPhaseTasks() throws Exception {
	Path cacheFile = cacheDir.getRelative("profile4.dat");
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "phase test", false,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	Thread thread1 = new Thread() {
	@Override public void run() {
	for (int i = 0; i < 100; i++) {
	Profiler.instance().logEvent(ProfilerTask.TEST, "thread1");
	}
	}
	};
	profiler.markPhase(ProfilePhase.INIT); // Empty phase.
	profiler.markPhase(ProfilePhase.LOAD);
	thread1.start();
	thread1.join();
	Thread.sleep(1);
	profiler.markPhase(ProfilePhase.ANALYZE);
	Thread thread2 = new Thread() {
	@Override public void run() {
	profiler.startTask(ProfilerTask.TEST, "complex task");
	for (int i = 0; i < 100; i++) {
	Profiler.instance().logEvent(ProfilerTask.TEST, "thread2a");
	}
	profiler.completeTask(ProfilerTask.TEST);
	profiler.markPhase(ProfilePhase.EXECUTE);
	for (int i = 0; i < 100; i++) {
	Profiler.instance().logEvent(ProfilerTask.TEST, "thread2b");
	}
	}
	};
	thread2.start();
	thread2.join();
	profiler.logEvent(ProfilerTask.TEST, "last task");
	Thread.sleep(1);
	profiler.stop();

	ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
	info.calculateStats();
	info.analyzeRelationships();
	// number of tasks: INIT(1) + LOAD(1) + Thread1.TEST(100) + ANALYZE(1)
	// + Thread2a.TEST(100) + TEST(1) + EXECUTE(1) + Thread2b.TEST(100) + TEST(1) + INFO(1)
	assertThat(info.allTasksById).hasSize(1 + 1 + 100 + 1 + 100 + 1 + 1 + 100 + 1 + 1);
	assertThat(info.tasksByThread).hasSize(3); // total number of threads
	// Phase0 contains only itself
	ProfileInfo.Task p0 = info.getPhaseTask(ProfilePhase.INIT);
	assertThat(info.getTasksForPhase(p0)).hasSize(1);
	// Phase1 contains itself and 100 TEST "thread1" tasks
	ProfileInfo.Task p1 = info.getPhaseTask(ProfilePhase.LOAD);
	assertThat(info.getTasksForPhase(p1)).hasSize(101);
	// Phase2 contains itself and 1 "complex task"
	ProfileInfo.Task p2 = info.getPhaseTask(ProfilePhase.ANALYZE);
	assertThat(info.getTasksForPhase(p2)).hasSize(2);
	// Phase3 contains itself, 100 TEST "thread2b" tasks and "last task"
	ProfileInfo.Task p3 = info.getPhaseTask(ProfilePhase.EXECUTE);
	assertThat(info.getTasksForPhase(p3)).hasSize(103);
	}

	@Test
	public void testCorruptedFile() throws Exception {
	Path cacheFile = cacheDir.getRelative("profile5.dat");
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(), "phase test", false,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	for (int i = 0; i < 100; i++) {
	profiler.startTask(ProfilerTask.TEST, "outer task " + i);
	profiler.logEvent(ProfilerTask.TEST, "inner task " + i);
	profiler.completeTask(ProfilerTask.TEST);
	}
	profiler.stop();

	ProfileInfo info = ProfileInfo.loadProfile(cacheFile);
	info.calculateStats();
	assertFalse(info.isCorruptedOrIncomplete());

	Path corruptedFile = cacheDir.getRelative("profile5bad.dat");
	FileSystemUtils.writeContent(
	corruptedFile, Arrays.copyOf(FileSystemUtils.readContent(cacheFile), 2000));
	info = ProfileInfo.loadProfile(corruptedFile);
	info.calculateStats();
	assertTrue(info.isCorruptedOrIncomplete());
	// Since root tasks will appear after nested tasks in the profile file and
	// we have exactly one nested task for each root task, then following will be
	// always true for our corrupted file:
	// 0 <= number_of_all_tasks - 2*number_of_root_tasks <= 1
	assertEquals(info.rootTasksById.size(), info.allTasksById.size() / 2);
	}

	@Test
	public void testUnsupportedProfilerRecord() throws Exception {
	Path dataFile = cacheDir.getRelative("profile5.dat");
	profiler.start(ProfiledTaskKinds.ALL, dataFile.getOutputStream(), "phase test", false,
	BlazeClock.instance(), BlazeClock.instance().nanoTime());
	profiler.startTask(ProfilerTask.TEST, "outer task");
	profiler.logEvent(ProfilerTask.EXCEPTION, "inner task");
	profiler.completeTask(ProfilerTask.TEST);
	profiler.startTask(ProfilerTask.SCANNER, "outer task 2");
	profiler.logSimpleTask(Profiler.nanoTimeMaybe(), ProfilerTask.TEST, "inner task 2");
	profiler.completeTask(ProfilerTask.SCANNER);
	profiler.stop();

	// Validate our test profile.
	ProfileInfo info = ProfileInfo.loadProfile(dataFile);
	info.calculateStats();
	assertFalse(info.isCorruptedOrIncomplete());
	assertEquals(2, info.getStatsForType(ProfilerTask.TEST, info.rootTasksById).count);
	assertEquals(0, info.getStatsForType(ProfilerTask.UNKNOWN, info.rootTasksById).count);

	// Now replace "TEST" type with something unsupported - e.g. "XXXX".
	InputStream in = new InflaterInputStream(dataFile.getInputStream(), new Inflater(false), 65536);
	byte[] buffer = new byte[60000];
	int len = in.read(buffer);
	in.close();
	assertTrue(len < buffer.length); // Validate that file was completely decoded.
	String content = new String(buffer, ISO_8859_1);
	int infoIndex = content.indexOf("TEST");
	assertTrue(infoIndex > 0);
	content = content.substring(0, infoIndex) + "XXXX" + content.substring(infoIndex + 4);
	OutputStream out = new DeflaterOutputStream(dataFile.getOutputStream(),
	new Deflater(Deflater.BEST_SPEED, false), 65536);
	out.write(content.getBytes(ISO_8859_1));
	out.close();

	// Validate that XXXX records were classified as UNKNOWN.
	info = ProfileInfo.loadProfile(dataFile);
	info.calculateStats();
	assertFalse(info.isCorruptedOrIncomplete());
	assertEquals(0, info.getStatsForType(ProfilerTask.TEST, info.rootTasksById).count);
	assertEquals(1, info.getStatsForType(ProfilerTask.SCANNER, info.rootTasksById).count);
	assertEquals(1, info.getStatsForType(ProfilerTask.EXCEPTION, info.rootTasksById).count);
	assertEquals(2, info.getStatsForType(ProfilerTask.UNKNOWN, info.rootTasksById).count);
	}

	@Test
	public void testResilenceToNonDecreasingNanoTimes() throws Exception {
	final long initialNanoTime = BlazeClock.instance().nanoTime();
	final AtomicInteger numNanoTimeCalls = new AtomicInteger(0);
	Clock badClock = new Clock() {
	@Override
	public long currentTimeMillis() {
	return BlazeClock.instance().currentTimeMillis();
	}

	@Override
	public long nanoTime() {
	return initialNanoTime - numNanoTimeCalls.addAndGet(1);
	}
	};
	Path cacheFile = cacheDir.getRelative("profile1.dat");
	profiler.start(ProfiledTaskKinds.ALL, cacheFile.getOutputStream(),
	"testResilenceToNonDecreasingNanoTimes", false, badClock, initialNanoTime);
	profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.TEST, "some task");
	profiler.stop();
	}

	private Clock getTestClock() {
	return BlazeClock.instance();
	}

	}