Commit Graph

9 Commits

Author SHA1 Message Date
Azat Khuzhin
891c601589 Fix ProfileEvents overlaps (for multiple queries) in clickhouse-local
Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
2022-04-12 22:27:12 +03:00
Azat Khuzhin
097e2f626d Do not overlap profile events snapshots for queries
Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
2022-04-12 20:54:56 +03:00
Azat Khuzhin
d9dd8f5f65 Fix filtering out snapshots from profile events
This fixes POSITION_OUT_OF_BOUND error:

    $ clickhouse-client --print-profile-events --profile-events-delay-ms=-1 -n -q 'select sleep(1); select 1'
    0
    [p1.azat.localdomain] 2022.04.12 19:31:48 [ 0 ] ContextLock: 9 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:48 [ 0 ] FunctionExecute: 1 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] MemoryTrackerUsage: 2132102 (gauge)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] NetworkReceiveElapsedMicroseconds: 139 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] NetworkSendBytes: 4850 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] NetworkSendElapsedMicroseconds: 1844 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:48 [ 0 ] Query: 1 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:48 [ 0 ] RWLockAcquiredReadLocks: 1 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:48 [ 0 ] SelectQuery: 1 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:48 [ 0 ] SelectedBytes: 1 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:48 [ 0 ] SelectedRows: 1 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] OSCPUVirtualTimeMicroseconds: 1842 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] OSReadChars: 426 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] OSWriteChars: 322 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] RealTimeMicroseconds: 1002689 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] SleepFunctionCalls: 1 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] SleepFunctionMicroseconds: 1000000 (increment)
    [p1.azat.localdomain] 2022.04.12 19:31:49 [ 0 ] UserTimeMicroseconds: 1843 (increment)
    1
    Error on processing query: Code: 11. DB::Exception: Position out of bound in Block::erase(), max position = 5. (POSITION_OUT_OF_BOUND) (version 22.4.1.1)
    (query: select 1)

Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
2022-04-12 20:54:56 +03:00
Azat Khuzhin
1fa3e6a426 Fix printing ProfileEvents on client for multiple queries
Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
2022-04-12 20:54:56 +03:00
Azat Khuzhin
d46eaadacc tests: do not use process substution in 02050_client_profile_events
bash does not waits then and so if the next line will be executed fast
enough, result of process substituted command can appers in stdout after
it.

Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
2022-04-12 20:54:56 +03:00
Azat Khuzhin
75789eb9a7 tests: improve 02050_client_profile_events
Signed-off-by: Azat Khuzhin <a.khuzhin@semrush.com>
2022-04-12 20:54:56 +03:00
Azat Khuzhin
2461cc5f93 tests: add thread_id into 02050_client_profile_events 2021-12-19 23:43:05 +03:00
Azat Khuzhin
b7f18e2333 tests: add more information for 02050_client_profile_events in case of failure
Sometimes [1] the test fails like this:

    2021-12-10 03:41:19 --- /usr/share/clickhouse-test/queries/0_stateless/02050_client_profile_events.reference	2021-12-10 03:23:43.000000000 -0500
    2021-12-10 03:41:19 +++ /tmp/clickhouse-test/0_stateless/02050_client_profile_events.617.stdout	2021-12-10 03:41:19.509611205 -0500
    2021-12-10 03:41:19 @@ -1,4 +1,3 @@
    2021-12-10 03:41:19  0
    2021-12-10 03:41:19 -SelectedRows: 131010 (increment)
    2021-12-10 03:41:19  OK
    2021-12-10 03:41:19  OK
    2021-12-10 03:41:19
    2021-12-10 03:41:19
    2021-12-10 03:41:19 Database: test_73d5o0

  [1]: https://s3.amazonaws.com/clickhouse-test-reports/32493/703213a6444f8014e3324df4b6e44d03fa351294/stateless_tests_flaky_check__address__actions_.html

And I did not find anything strange in server logs (and there was 0
exceptions).
2021-12-19 23:43:05 +03:00
Azat Khuzhin
424bf6fcf4 client: add ability to print raw profile events
This can be useful for debugging and for testing (since you will not
need to obtain query_id and look at query_log).

v2:
- mark test as long
- add option to docs
- add type of profile event into logs too
v3:
- resolve conflicts
- and fix onProfileEvents callback
v4:
- add --print-profile-events separate switch
2021-10-19 00:54:38 +03:00