Task.getShallowTrace() does not provide consistent elapsed time for different type of tasks
mchen07 opened this issue · 5 comments
ParSeq users sometimes need to track the elapsed time for a task they constructed. To do this, they normally add a listener to the task they constructed through parseq API as follows, with the understanding that this metric listener should be able to tell the total elapsed time for the whole task constructed (not just the last part of task through composition API). However, this understanding does not hold for all types of tasks. For example, in the following code snippet, for the first Task constructed using map, it will only show the elapsed time for that map part, not the whole task. But for the second task wrapping the first task using flatMap, it will show the elapsed time for the whole task. This API inconsistency is really confusing the user, we should try to address that in a backward compatible way. Actually there is a system hidden task as the wrapper for even the first task, we should be able to use that to provide the elapsed time for the whole task.
private class TaskAwareListener<R> implements PromiseListener<R> {
private final Task<R> _task;
public TaskAwareListener(Task<R> task) {
_task = task;
}
@Override
public void onResolved(Promise<R> promise) {
ShallowTrace shallowTrace = _task.getShallowTrace();
System.out.println("elapsed time: " + (shallowTrace.getEndNanos() - shallowTrace.getStartNanos())/1000000);
}
}
private static Task<String> getSuccessTask() {
return Task.value("Hello world!");
}
@Test
public void testMap() {
Task<Integer> wrappedTask = getSuccessTask().map(String::length);
wrappedTask.addListener(new TaskAwareListener<>(wrappedTask));
runAndWait("AbstractTaskTest.testMap", wrappedTask);
}
@Test
public void testMapWrap() {
Task<Integer> task = getSuccessTask().map(String::length);
Task<Integer> wrappedTask = Task.value(null).flatMap(s -> task);
wrappedTask.addListener(new TaskAwareListener<>(wrappedTask));
runAndWait("AbstractTaskTest.testMapWrap", wrappedTask);
}
Not sure if I understand the request/issue.
public class ParseqTest extends BaseEngineParTest {
private class TaskAwareListener<R> implements PromiseListener<R> {
private final Task<R> _task;
public TaskAwareListener(Task<R> task) {
_task = task;
}
@Override
public void onResolved(Promise<R> promise) {
ShallowTrace shallowTrace = _task.getShallowTrace();
System.out.println("elapsed time: " + (shallowTrace.getNativeEndNanos() - shallowTrace.getNativeStartNanos())/1000000.0);
}
}
@Test
public void testMap() throws Exception{
Task<Integer> task = Task.value("hello").map(String::length);
task.addListener(new TaskAwareListener<>(task));
runAndWait("AbstractTaskTest.testMap", task);
System.out.print(task.getId());
System.out.print(TraceUtil.getJsonTrace(task));
System.out.println("elapsed time: " +
(task.getShallowTrace().getNativeEndNanos()
- task.getShallowTrace().getNativeStartNanos())/1000000.0);
}
@Test
public void testMapWrap() throws Exception{
Task<Integer> task = Task.value("hello").map(String::length);
Task<Integer> wrappedTask = Task.value(null).flatMap(s -> task);
wrappedTask.addListener(new TaskAwareListener<>(wrappedTask));
runAndWait("AbstractTaskTest.testMapWrap", wrappedTask);
System.out.print(wrappedTask.getId());
System.out.print(TraceUtil.getJsonTrace(wrappedTask));
System.out.println("elapsed time: " +
(wrappedTask.getShallowTrace().getNativeEndNanos()
- wrappedTask.getShallowTrace().getNativeStartNanos())/1000000.0);
}
}
The output times looks right to me.
As described in the bug description, "for the first Task constructed using map, it will only show the elapsed time for that map part, not the whole task. But for the second task wrapping the first task using flatMap, it will show the elapsed time for the whole task". If you open parseq tracevis, you can see if your output time is only corresponding to that one part of map operation, or the summation of all time spent on the complete task in flatMap case.
Hi Min, I also did a test.
Can you elaborate your question a bit more? I pasted examples below.
The number is roughly correct, (though seems a bit off for map case)
Here are the result I got from these two tests:
elapsed time: 10
2021-01-06 14:06:55,787 [main] INFO com.linkedin.parseq.ParSeqUnitTestHelper: Trace [AbstractTaskTest.testMap]:
{"planId":2,"planClass":"com.linkedin.parseq.FusionTask","traces":[{"id":0,"name":"success","resultType":"SUCCESS","hidden":false,"systemHidden":false,"startNanos":7692691795558890,"pendingNanos":7692691795627785,"endNanos":7692691795668426},{"id":1,"name":"async fused","resultType":"SUCCESS","hidden":false,"systemHidden":true,"startNanos":7692691787750384,"pendingNanos":7692691794758384,"endNanos":7692691798373297,"taskType":"fusion"},{"id":1000,"name":"map: com.linkedin.parseq.TestTask$$Lambda$8/89387388","resultType":"SUCCESS","hidden":false,"systemHidden":false,"startNanos":7692691797508376,"pendingNanos":7692691798331334,"endNanos":7692691798339808}],"relationships":[{"relationship":"SUCCESSOR_OF","from":1000,"to":0},{"relationship":"PARENT_OF","from":1,"to":1000},{"relationship":"PARENT_OF","from":1,"to":0}]}
elapsed time: 17
2021-01-06 14:07:11,398 [main] INFO com.linkedin.parseq.ParSeqUnitTestHelper: Trace [AbstractTaskTest.testMapWrap]:
{"planId":5,"planClass":"com.linkedin.parseq.Task$1","traces":[{"id":0,"name":"success","resultType":"SUCCESS","hidden":false,"systemHidden":false,"startNanos":7692707410877046,"pendingNanos":7692707410915088,"endNanos":7692707410922916},{"id":1,"name":"async fused","resultType":"SUCCESS","hidden":false,"systemHidden":true,"startNanos":7692707409632801,"pendingNanos":7692707410852670,"endNanos":7692707411099104,"taskType":"fusion"},{"id":2,"name":"value","resultType":"SUCCESS","hidden":false,"systemHidden":false,"startNanos":7692707405287250,"pendingNanos":7692707406955261,"endNanos":7692707406986765,"taskType":"fusion"},{"id":3,"name":"fused","resultType":"SUCCESS","hidden":false,"systemHidden":true,"startNanos":7692707403926370,"pendingNanos":7692707408986833,"endNanos":7692707409026064,"taskType":"fusion"},{"id":4,"name":"flatMap: com.linkedin.parseq.TestTask$$Lambda$13/485041780","resultType":"SUCCESS","hidden":false,"systemHidden":false,"startNanos":7692707394866388,"pendingNanos":7692707402980530,"endNanos":7692707412260193,"taskType":"flatten"},{"id":1000,"name":"flatMap: com.linkedin.parseq.TestTask$$Lambda$13/485041780","resultType":"SUCCESS","hidden":false,"systemHidden":true,"startNanos":7692707408897413,"pendingNanos":7692707408956569,"endNanos":7692707408956569},{"id":1001,"name":"map: com.linkedin.parseq.TestTask$$Lambda$8/89387388","resultType":"SUCCESS","hidden":false,"systemHidden":false,"startNanos":7692707410977671,"pendingNanos":7692707411040362,"endNanos":7692707411048934}],"relationships":[{"relationship":"SUCCESSOR_OF","from":1,"to":3},{"relationship":"PARENT_OF","from":1,"to":0},{"relationship":"PARENT_OF","from":4,"to":3},{"relationship":"SUCCESSOR_OF","from":1001,"to":0},{"relationship":"SUCCESSOR_OF","from":1000,"to":2},{"relationship":"PARENT_OF","from":3,"to":2},{"relationship":"PARENT_OF","from":4,"to":1},{"relationship":"PARENT_OF","from":1,"to":1001},{"relationship":"PARENT_OF","from":3,"to":1000}]}
After team discussion, will close the issue for now since we cannot reproduce. Feel free to reopen when the issue re-emerged