You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@impala.apache.org by "Pranay Singh (Code Review)" <ge...@cloudera.org> on 2017/10/05 01:20:58 UTC
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Pranay Singh has uploaded this change for review. ( http://gerrit.cloudera.org:8080/8215
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
IMPALA-5142 EventSequence displays negative elapsed time.
EventSequence may display a negative elapsed time if ClientRequestState is done
while EventSequence::MarkEvent() is in progress.
The time is calculated based on POSIX clock_gettime() which uses CLOCK_MONOTONIC that
will always give a time in increasing time order. In this case the cause of negative
delay is start time becoming greater than end time, as the difference of latter and
the former is used to compute the delay.
The negative delay case can happen if EventSequence::Start() is called on the same
EventSequence for which EventSequence::MarkEvent() is in progress.It can be serialized
by reordering the lock in EventSequence::MarkEvent() but that may be a performance
overhead, calling ElapsedTime() with lock held.So this patch fixes the issue by returning
a 0 delay value when such an issue ever happens rather than returning a negative delay
value.
Testing:
-------
Ran all the front-end/backend and end-end tests.
Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
---
M be/src/util/stopwatch.h
1 file changed, 6 insertions(+), 0 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/15/8215/1
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newchange
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 1
Gerrit-Owner: Pranay Singh
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has submitted this change and it was merged. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
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 <dh...@cloudera.com>
Tested-by: Impala Public Jenkins
---
M be/src/util/runtime-profile-counters.h
1 file changed, 6 insertions(+), 0 deletions(-)
Approvals:
Dan Hecht: Looks good to me, approved
Impala Public Jenkins: Verified
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 8
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Pranay Singh
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Pranay Singh has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 4:
(2 comments)
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h
File be/src/util/runtime-profile-counters.h:
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h@326
PS4, Line 326: bool eventlist_sorted = true;
: int64_t prev = 0L;
: for (const Event& event: events_) {
: if (event.second < prev) {
: eventlist_sorted = false;
: break;
: }
: prev = event.second;
: }
:
> why bother with this? the list is pretty short and this isn't a critical pa
Since the list is sorted in most of the times calling sort() may be expensive (if in future # of events becomes large), hence I'll use the std::is_sorted() instead.
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h@336
PS4, Line 336: [](Event const &event1,
> nit: how about breaking the line before the [] instead of in the middle of
Done
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 4
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Wed, 01 Nov 2017 22:24:19 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Pranay Singh has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 2:
(2 comments)
http://gerrit.cloudera.org:8080/#/c/8215/2/be/src/util/runtime-profile.cc
File be/src/util/runtime-profile.cc:
http://gerrit.cloudera.org:8080/#/c/8215/2/be/src/util/runtime-profile.cc@658
PS2, Line 658: event_sequence.second->GetEvents(&events);
: if (last == 0 && events.size() > 0) last = events.back().second;
> that looks like it could be inconsistent with the sorted order
Introduced a fix to check and fix the event order in event list in GetEvents()
http://gerrit.cloudera.org:8080/#/c/8215/2/be/src/util/runtime-profile.cc@672
PS2, Line 672:
> runtime-profile-test.cc has a test case that expects GetEvents() to be in o
The events are printed in the list order and as they are printed the value of current is decremented from previous to get the elapsed time. So we are getting a list of events that are not in order.
I've moved the sorting code in GetEvents() as per your suggestion which seems to be more plausible.
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 2
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Wed, 25 Oct 2017 18:33:36 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Hello Dan Hecht,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/8215
to look at the new patch set (#6).
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
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
---
M be/src/util/runtime-profile-counters.h
1 file changed, 6 insertions(+), 0 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/15/8215/6
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 6
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Dan Hecht (Code Review)" <ge...@cloudera.org>.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 4:
(2 comments)
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h
File be/src/util/runtime-profile-counters.h:
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h@326
PS4, Line 326: bool eventlist_sorted = true;
: int64_t prev = 0L;
: for (const Event& event: events_) {
: if (event.second < prev) {
: eventlist_sorted = false;
: break;
: }
: prev = event.second;
: }
:
why bother with this? the list is pretty short and this isn't a critical path, so I think it should be fine to always call sort().
(and if you were to do that, you might as well use std::is_sorted())
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h@336
PS4, Line 336: [](Event const &event1,
nit: how about breaking the line before the [] instead of in the middle of the lambda param list?
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 4
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Wed, 01 Nov 2017 20:17:40 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Dan Hecht (Code Review)" <ge...@cloudera.org>.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 2:
(2 comments)
http://gerrit.cloudera.org:8080/#/c/8215/2/be/src/util/runtime-profile.cc
File be/src/util/runtime-profile.cc:
http://gerrit.cloudera.org:8080/#/c/8215/2/be/src/util/runtime-profile.cc@658
PS2, Line 658: event_sequence.second->GetEvents(&events);
: if (last == 0 && events.size() > 0) last = events.back().second;
that looks like it could be inconsistent with the sorted order
http://gerrit.cloudera.org:8080/#/c/8215/2/be/src/util/runtime-profile.cc@672
PS2, Line 672:
runtime-profile-test.cc has a test case that expects GetEvents() to be in order. that case isn't correct if we are saying that GetEvents() returns events unsorted.
Also, the comment for events_ says the events are in sorted order.
I think we should either:
(a) maintain events in sorted order, or
(b) do this sort inside GetEvents()
either way the property is that GetEvents() always returns events in increasing time order, which seems like the most straightforward API.
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 2
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Wed, 25 Oct 2017 16:46:56 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Hello Dan Hecht,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/8215
to look at the new patch set (#3).
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
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
---
M be/src/util/runtime-profile-counters.h
1 file changed, 19 insertions(+), 0 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/15/8215/3
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 3
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Pranay Singh has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 1:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/8215/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/8215/1//COMMIT_MSG@22
PS1, Line 22: value.
> but the code isn't synchronized at all, so you could (in theory) read a gar
That's right since the code not synchronized we can read a garbage start_ which is the case here.I was wondering wether there will be performance overhead if lock is used to seialize. So instead of printing a negative value I'm printing 0.
The Start() is called from ClientRequestState()
ClientRequestState::ClientRequestState()
{
query_events_ = summary_profile_->AddEventSequence("Query Timeline");···················
query_events_->Start();
}
whereas ElapsedTime()
RuntimeProfile::EventSequence::MarkEvent()
{
sw_.ElapsedTime();
}
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 1
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Tue, 17 Oct 2017 03:48:03 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Dan Hecht (Code Review)" <ge...@cloudera.org>.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 6: Code-Review+2
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 6
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Thu, 02 Nov 2017 19:24:20 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Dan Hecht (Code Review)" <ge...@cloudera.org>.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 7: Code-Review+2
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 7
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Thu, 02 Nov 2017 19:24:26 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 7: Verified+1
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 7
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Thu, 02 Nov 2017 22:53:30 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Hello Dan Hecht,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/8215
to look at the new patch set (#5).
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
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
---
M be/src/util/runtime-profile-counters.h
1 file changed, 14 insertions(+), 0 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/15/8215/5
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 5
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Impala Public Jenkins (Code Review)" <ge...@cloudera.org>.
Impala Public Jenkins has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 7:
Build started: https://jenkins.impala.io/job/gerrit-verify-dryrun/1426/
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 7
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Impala Public Jenkins
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Thu, 02 Nov 2017 19:24:31 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Pranay Singh has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 5:
(3 comments)
http://gerrit.cloudera.org:8080/#/c/8215/5/be/src/util/runtime-profile-counters.h
File be/src/util/runtime-profile-counters.h:
http://gerrit.cloudera.org:8080/#/c/8215/5/be/src/util/runtime-profile-counters.h@327
PS5, Line 327: [](Event const &event1, Event const &event2) {
: return event1.second < event2.second;
> rather than creating a tmp eventlist_sorted, you should create a temp for t
I'm dropping this logic to call the sort() all the time to make the result more predictable each time this function gets called and also since the event list will be small so sorting won't be that expensive.
http://gerrit.cloudera.org:8080/#/c/8215/5/be/src/util/runtime-profile-counters.h@330
PS5, Line 330: == false
> our style uses ! rather than == false
Since I'm not checking the event list to be sorted so I won't need this anymore.
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h
File be/src/util/runtime-profile-counters.h:
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h@326
PS4, Line 326: bool eventlist_sorted = std::is_sorted(events_.begin(), events_.end(),
: [](Event const &event1, Event const &event2) {
: return event1.second < event2.second;
: });
: if (eventlist_sorted == false) {
: std::sort(events_.begin(), events_.end(),
: [](Event const &event1, Event const &event2) {
: return event1.second < event2.second;
: });
:
> the flipside is that this becomes a cliff in the sense that normally it wil
Done as suggested kept the functionality simple, removed the logic of having an extra check.
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 5
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Wed, 01 Nov 2017 23:01:41 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Dan Hecht (Code Review)" <ge...@cloudera.org>.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 1:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/8215/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/8215/1//COMMIT_MSG@22
PS1, Line 22: value.
but the code isn't synchronized at all, so you could (in theory) read a garbage start_ if it's being modified concurrently.
What are the callsites of Start() and ElapsedTime() in question?
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 1
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Comment-Date: Tue, 17 Oct 2017 00:16:45 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Hello Dan Hecht,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/8215
to look at the new patch set (#4).
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
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
---
M be/src/util/runtime-profile-counters.h
1 file changed, 19 insertions(+), 0 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/15/8215/4
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 4
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Dan Hecht (Code Review)" <ge...@cloudera.org>.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 1:
> (1 comment)
But who is the caller of MarkEvent()? How can that be happening in concurrently with the construction of the ClientRequestState()? No one would have a reference to it yet...
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 1
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Tue, 17 Oct 2017 16:05:26 +0000
Gerrit-HasComments: No
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Hello Dan Hecht,
I'd like you to reexamine a change. Please visit
http://gerrit.cloudera.org:8080/8215
to look at the new patch set (#2).
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
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. This patch fixes the issue by
sorting the EventList before printing.Since reordering the lock in
EventSequence::MarkEvent() will involve holding the lock across clock_gettime().
Testing:
Ran all the front-end/backend and end-end tests.
Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
---
M be/src/util/runtime-profile.cc
1 file changed, 7 insertions(+), 0 deletions(-)
git pull ssh://gerrit.cloudera.org:29418/Impala-ASF refs/changes/15/8215/2
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 2
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Dan Hecht (Code Review)" <ge...@cloudera.org>.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 4:
(3 comments)
http://gerrit.cloudera.org:8080/#/c/8215/5/be/src/util/runtime-profile-counters.h
File be/src/util/runtime-profile-counters.h:
http://gerrit.cloudera.org:8080/#/c/8215/5/be/src/util/runtime-profile-counters.h@327
PS5, Line 327: int64_t prev = 0L;
: for (const Event& event: events_) {
rather than creating a tmp eventlist_sorted, you should create a temp for this lamba (you can use "auto" for that), since it's used twice and must be consistent in order for this code to make sense.
http://gerrit.cloudera.org:8080/#/c/8215/5/be/src/util/runtime-profile-counters.h@330
PS5, Line 330: = false;
our style uses ! rather than == false
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h
File be/src/util/runtime-profile-counters.h:
http://gerrit.cloudera.org:8080/#/c/8215/4/be/src/util/runtime-profile-counters.h@326
PS4, Line 326: bool eventlist_sorted = true;
: int64_t prev = 0L;
: for (const Event& event: events_) {
: if (event.second < prev) {
: eventlist_sorted = false;
: break;
: }
: prev = event.second;
: }
:
> Since the list is sorted in most of the times calling sort() may be expensi
the flipside is that this becomes a cliff in the sense that normally it will be fast, but every once in a while (when the race occurs), we'll pay the cost of sort(). If we always call sort(), then the performance is more predictable.
I don't think the event list will ever be so long that this matters one way or another, so simplest seems best. That said, I don't feel strongly if you really want to keep the check.
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 4
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Wed, 01 Nov 2017 22:31:42 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Pranay Singh (Code Review)" <ge...@cloudera.org>.
Pranay Singh has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 1:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/8215/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/8215/1//COMMIT_MSG@22
PS1, Line 22: value.
> That's right since the code not synchronized we can read a garbage start_ w
In the thread doing ClientRequestState::ClientRequestState()
a) When the function AddEventSequence() is called, an EventSequence with the name is looked for, if found then the EventSequence is returned else a new event sequence gets created.
b) Then after the query_events->Start(0 resets the monotonic time for the EventSequence, so say in this case a matching name for "Query Timeline" was found
In another thread which is done doing AdmissionController::AdmitQuery(QuerySchedule* schedule)
in the mean time will have ScopedEvent destroyed for the same EventSequence and since they are not serialized we may hit upon this issue.
/// Utility class to mark an event when the object is destroyed.
class ScopedEvent {
.....
/// Mark the event when the object is destroyed
~ScopedEvent() {
event_sequence_->MarkEvent(label_); --->
}
};
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 1
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Tue, 17 Oct 2017 21:55:54 +0000
Gerrit-HasComments: Yes
[Impala-ASF-CR] IMPALA-5142 EventSequence displays negative elapsed time.
Posted by "Dan Hecht (Code Review)" <ge...@cloudera.org>.
Dan Hecht has posted comments on this change. ( http://gerrit.cloudera.org:8080/8215 )
Change subject: IMPALA-5142 EventSequence displays negative elapsed time.
......................................................................
Patch Set 1:
(1 comment)
http://gerrit.cloudera.org:8080/#/c/8215/1//COMMIT_MSG
Commit Message:
http://gerrit.cloudera.org:8080/#/c/8215/1//COMMIT_MSG@22
PS1, Line 22: value.
> In the thread doing ClientRequestState::ClientRequestState()
There is only one call to AddEventSequence("Query Timeline") per query though, right? so how does another thread operate on that event_sequence_ before the constructor of CRS() returns?
Are you able to reproduce this problem? If so, can you change your if-stmt to a DCHECK() and put the backtrace in the JIRA when the DCHECK fires.
--
To view, visit http://gerrit.cloudera.org:8080/8215
To unsubscribe, visit http://gerrit.cloudera.org:8080/settings
Gerrit-Project: Impala-ASF
Gerrit-Branch: master
Gerrit-MessageType: comment
Gerrit-Change-Id: I8c944396d96473b17b453da3e913ffc56680a896
Gerrit-Change-Number: 8215
Gerrit-PatchSet: 1
Gerrit-Owner: Pranay Singh
Gerrit-Reviewer: Dan Hecht <dh...@cloudera.com>
Gerrit-Reviewer: Pranay Singh
Gerrit-Comment-Date: Tue, 17 Oct 2017 23:30:42 +0000
Gerrit-HasComments: Yes