Repository: incubator-impala Updated Branches: refs/heads/master 98490925c -> 1803b403e
IMPALA-5142 EventSequence displays negative elapsed time. EventSequence::EventList which stores the Event in increasing time order may have at times Events that are not stored in increasing time order. This may happen when concurrently EventSequence::MarkEvent() is called for different Events in the same EventSequence. The incorrect time order of Event in EventList results in a negative value being displayed, which is the issue reported in this JIRA. The issue can be fixed either be re-ordering the lock in EventSequence::MarkEvent() or by sorting the EventList before printing. Reordering of lock in EventSequence::MarkEvent() will involve holding the lock across clock_gettime() so that approach is not taken. This patch fixes the issue by sorting the EventList in GetEvents() as this function is expected to return sorted list of events based on time. Testing: Ran all the front-end/backend and end-end tests. Change-Id: I8c944396d96473b17b453da3e913ffc56680a896 Reviewed-on: http://gerrit.cloudera.org:8080/8215 Reviewed-by: Dan Hecht <[email protected]> Tested-by: Impala Public Jenkins Project: http://git-wip-us.apache.org/repos/asf/incubator-impala/repo Commit: http://git-wip-us.apache.org/repos/asf/incubator-impala/commit/eeb32426 Tree: http://git-wip-us.apache.org/repos/asf/incubator-impala/tree/eeb32426 Diff: http://git-wip-us.apache.org/repos/asf/incubator-impala/diff/eeb32426 Branch: refs/heads/master Commit: eeb32426a3724dc127695368ef3c49ca76e437cf Parents: 9849092 Author: Pranay <[email protected]> Authored: Wed Oct 4 14:09:44 2017 -0700 Committer: Impala Public Jenkins <[email protected]> Committed: Thu Nov 2 22:53:31 2017 +0000 ---------------------------------------------------------------------- be/src/util/runtime-profile-counters.h | 6 ++++++ 1 file changed, 6 insertions(+) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/incubator-impala/blob/eeb32426/be/src/util/runtime-profile-counters.h ---------------------------------------------------------------------- diff --git a/be/src/util/runtime-profile-counters.h b/be/src/util/runtime-profile-counters.h index 40f72c6..9227e66 100644 --- a/be/src/util/runtime-profile-counters.h +++ b/be/src/util/runtime-profile-counters.h @@ -319,6 +319,12 @@ class RuntimeProfile::EventSequence { void GetEvents(std::vector<Event>* events) { events->clear(); boost::lock_guard<SpinLock> event_lock(lock_); + /// It's possible that concurrent events can be logged out of sequence. + /// So sort the events each time we are here. + std::sort(events_.begin(), events_.end(), + [](Event const &event1, Event const &event2) { + return event1.second < event2.second; + }); events->insert(events->end(), events_.begin(), events_.end()); }
