[jira] [Resolved] (IMPALA-5142) EventSequence::MarkEvent() may record concurrent events out of serialized order

["Pranay Singh (JIRA)" <ji...@apache.org>]

     [ https://issues.apache.org/jira/browse/IMPALA-5142?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Pranay Singh resolved IMPALA-5142.
----------------------------------
    Resolution: Resolved

This issue has been resolved by the below checkin

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

> EventSequence::MarkEvent() may record concurrent events out of serialized order
> -------------------------------------------------------------------------------
>
>                 Key: IMPALA-5142
>                 URL: https://issues.apache.org/jira/browse/IMPALA-5142
>             Project: IMPALA
>          Issue Type: Bug
>          Components: Distributed Exec
>    Affects Versions: Impala 2.7.0
>            Reporter: Mostafa Mokhtar
>            Assignee: Pranay Singh
>            Priority: Trivial
>              Labels: ramp-up, trivial
>
> When the event for first dynamic filter is received ahead of all fragments started the query timeline prints a negative time value for "fragment instances started"
> {code}
>        - Planning finished: 790.555ms (32.872ms)
>     Query Timeline: 2m40s
>        - Query submitted: 7.295ms (7.295ms)
>        - Planning finished: 1s397ms (1s390ms)
>        - Submit for admission: 3s059ms (1s661ms)
>        - Completed admission: 3s087ms (27.810ms)
>        - Ready to start 90 fragment instances: 3s527ms (440.540ms)
>        - First dynamic filter received: 7s851ms (4s323ms)
>        - All 90 fragment instances started: 7s851ms (-88037.000ns)
>        - Rows available: 2m28s (2m20s)
>        - First row fetched: 2m28s (51.725ms)
>        - Unregister query: 2m30s (1s459ms)
>      - ComputeScanRangeAssignmentTimer: 770.794ms
> {code}
> Query timeline when filter arrive after all fragments starting. 
> {code}
>     Query Timeline: 17s011ms
>        - Query submitted: 174.449us (174.449us)
>        - Planning finished: 209.847ms (209.672ms)
>        - Submit for admission: 255.819ms (45.971ms)
>        - Completed admission: 256.212ms (393.074us)
>        - Ready to start 90 fragment instances: 283.582ms (27.370ms)
>        - All 90 fragment instances started: 627.013ms (343.430ms)
>        - First dynamic filter received: 954.223ms (327.209ms)
>        - Rows available: 16s393ms (15s439ms)
>        - First row fetched: 16s705ms (311.586ms)
>        - Unregister query: 16s871ms (165.908ms)
>      - ComputeScanRangeAssignmentTimer: 13.125ms
> {code}



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)