Sometimes negative parse times are shown

[wladimirleite]

I noticed this a few times, but didn't take a screenshot. The screenshots below were taken by @aberenguel. I will try to get more information and hopefully reproduce this situation.

[lfcnassif]

This is weird. There is a non trivial logic for container parsers to subtract the processing time of their children from the parent container parsing time, but those highlighted parsers above aren't container parsers.

[wladimirleite]

I processed twice the same E01 that @aberenguel observed the negative parse times, but couldn't not reproduce it. I added a warning in the log if any negative time is added to the total time, which should not happen. Got no negative times in that E01, but processing other evidence files I got some of these warnings, but it didn't happen every time. I have a few ideas about possible causes... I will try to create a synthetic input to increase the chances of reproducing the issue.

[wladimirleite]

I managed to reproduce the issue processing a folder with 10 copies of test.zip. I believe that the way timeInDepth works in ParsingTask is causing the issue, as siblings evidences may affect each other. I added the following debug message to warn about any negative time added, in ParsingTask:

        } finally {
            depth--;
            long diff = System.nanoTime() / 1000 - start;
            Long subitemsTime = timeInDepth.remove(depth + 1);
            if (subitemsTime == null)
                subitemsTime = 0L;
            time.addAndGet(diff - subitemsTime);

            // DEBUG MESSAGE
            if (diff < subitemsTime) {
                System.err.println(">>>NEGATIVE\ndepth=" + depth + "\nName=" + evidence.getName() + "\nParser="
                        + parserName + "\ntimeInDepth=" + timeInDepth + "\ndiff=" + diff + "\nsubitemsTime="
                        + subitemsTime + "\n");
            }
        }

[lfcnassif]

Good catch! I just took a look at the code and maybe this actually is being caused by a duplicated variable name depth as an int attribute of the class and as an Integer in parseEmbedded method. Could you fix this duplication and test with your test data?

[lfcnassif]

Sorry @tc-wleite, I just saw you sent the test samples. I was running a lot a tests related to #1958. I will test my suggestion when I return back to home.

[wladimirleite]

Sorry @tc-wleite, I just saw you sent the test samples. I was running a lot a tests related to #1958. I will test my suggestion when I return back to home.

No problem! I already tested it here and it solved the negative parsing times issue (at least with the sample ZIP files I was using). I wrote an alternative solution, not using timeInDepth map (and simplyfing a few other related things). I am running a few more tests with real evidence files, and will submit a PR later.