No data about SELECT queries in Superset in ClickHouse table system.processes

[berlicon]

In ClickHouse there is a table system.processes which contains info about all queries running right now. And we can kill any too long query.
See:
https://clickhouse.com/docs/en/operations/system-tables/processes
https://clickhouse.com/docs/en/sql-reference/statements/kill#kill-query
https://clickhouse.com/docs/en/operations/system-tables/query_log

This table works great. I can run any long (>5sec) query any type (select, insert, update, delete, alter) then I can see that query in system.processes and kill that query by query_id. I checked this functionality in DBeaver. Also I tested that in Superset / SQLLab. All queries running in SQLLab I can see in system.processes except of SELECT queries. I want to see all queries from Superset, not only ins/upd/del but also SELECT queries.

How to reproduce the bug:

1. Connect ClickHouse DB to Superset.
2. Open DBeaver and on current ClickHouse DB create table with a lot of data. Execute SQL code below:
   create table eso.t2(v String) ENGINE = MergeTree() order by v
   insert into eso.t2(v) values(generateUUIDv4())
   insert into eso.t2(v) SELECT v from eso.t2 -- repeat that row 20+ times to have 1m+ rows in table eso.t2
3. Open Superset/SQLLab, select UI LIMIT: 1m+ and run long query:
   SELECT v, generateUUIDv4() as uid from eso.t2 limit 500000
4. In DBeaver on current ClickHouse DB run query:
   SELECT query, * FROM system.processes where query not like '%processes%'
5. There are no rows returned by query. This is the BUG. Exprected result: returned one row from system.processes with query from point 3.

Success case: I run in Superset query:
insert into eso.t2(v) SELECT v from eso.t2
... and can see that query in system.processes.

[den-crane]

SELECT v, generateUUIDv4() as uid from eso.t2 limit 500000 format Null;
0 rows in set. Elapsed: 0.073 sec. Processed 851.97 thousand rows, 38.34 MB (11.75 million rows/s., 528.65 MB/s.)

The most probably this query returned data to the superset instantly. And superset shows its own processing.
Try to add a sleep(2) to the query to make it slower artificially.

SELECT v, generateUUIDv4() as uid, sleep(2) from eso.t2 limit 500000 format Null;
0 rows in set. Elapsed: 4.048 sec. Processed 835.58 thousand rows, 37.60 MB (206.43 thousand rows/s., 9.29 MB/s.)
Peak memory usage: 59.72 MiB.

[berlicon]

@den-crane - It helps, thank you! This solution generates some additional problems but they could be resolved. I mean user of our app doesn't want to add column "sleep(1)" to SELECT query, so I modified sql query in Superset in method superset\sql_lab.py / execute_sql_statement(). And next I should remove additional column "sleep(1)" from resultset in Superset / SQLLab.

Second solution was to get active queries from Superset table "query". But this solution has a lot of issues - many expired sql queries in table in "running" status; we should join queries from Superset table with ClickHouse table system.query_log to get query_id to have possibility to kill query but rows not identical etc.

So, we have a workaround. But original problem still exists. Should I close the issue?

[den-crane]

I don't really understand what is the problem. Why do you need queries in system.processes ?
system.processes shows current queries but if a query runs several milliseconds it's really hard to notice it in system.processes. And you don't need to kill it because it's already finished.

[berlicon]

We create a solution where users could run any queries to ClickHouse DB via Superset. And admin could be able to see all queries and kill some of them (long queries). And we saw that admin can not see SELECT queries and we need some approach to fix it.

[Algunenano]

So, we have a workaround. But original problem still exists. Should I close the issue?

That wasn't a workaround, it was to help visualise that the problem is not at the ClickHouse level. Please check the logs of those supposedly running queries to confirm. If the query has already finished there is obviously no way, or need, to cancel it.

[berlicon]

@Algunenano - No, the problem is not about "query has already finished there is obviously no way, or need, to cancel it". The query was really long (>30sec) and that SELECT query I didn't see in system.processes. Fortunately I applied solution from @den-crane (add column sleep(1) to SELECT query and next removed that column from result). As I understand, the problem will not be fixed on Superset (apache/superset#28007 (comment)) neither on ClickHouse (#62604 (comment)) side. Fortunately we have a workaround. So, ticket could be closed.

[Algunenano]

If adding a sleep() call makes it appear, that means that without the sleep the query is too fast to be detected. Please check your query_logs to see if when the query started and finished and when you checked if it was alive.

If the query doesn't appear in system.processes while it's still running that would be a major bug on CH side.

[berlicon]

I tested the same query in DBeaver and in Superset.

1. On DBeaver all is OK. I run query on one tab and check system.processes. The query present in system.processes all the time it is running. Also ClickHouse insert one row to system.query_log with QueryStart with time when query was started. After query finished, query disappeared from system.processes and one addition row was inserted to system.query_log with QueryFinish with time when query was finished.
2. I run the same SELECT query in Superset with same LIMIT. No data in system.processes while query was started, running and finished. After 5-6sec ClickHouse insert two rows to system.query_log with equal QueryStart and QueryFinish.
3. If I add sleep(1) to SELECT query and run it in Superset, I see correct behaviour. Query appears and disappears in procesess and I can see two rows in query_log with different time QueryStart and QueryFinish.
4. If I run another long query in Superset (insert into t select * from t) I also can see correct behaviour.

[den-crane]

@berlicon Please share select * from system.query_log where query_id = (both/all rows QueryStart/QueryFinish) for DBeaver and Superset.

I guess the difference that DBeaver fetches data slowly using HTTP protocol and this is accounted as query execution, but Superset fetches instantly using TCP protocol (because of another column format, another blocksize).

It should be visible in system.query_log.profileEvents

[den-crane]

it looks like this

create database eso;
create table eso.t2(v String) ENGINE = MergeTree() order by v as  select generateUUIDv4() from numbers(1e7);

curl --limit-rate 5M -o /dev/null 'http://localhost:8123/?query_id=dbeaver&query=SELECT+v,+generateUUIDv4()+from+eso.t2+limit+500000'

clickhouse-client --query_id=superset -q 'SELECT v, generateUUIDv4() from eso.t2 limit 500000' >/dev/null


SELECT
    query_id,
    event_time,
    query_duration_ms
FROM system.query_log
WHERE (query_id IN ('superset', 'dbeaver')) AND (type = 'QueryFinish')
ORDER BY query_id ASC

┌─query_id─┬──────────event_time─┬─query_duration_ms─┐
│ dbeaver  │ 2024-04-18 13:58:30 │              5465 │
│ superset │ 2024-04-18 13:59:26 │                29 │
└──────────┴─────────────────────┴───────────────────┘

[berlicon]

@den-crane
Superset:

1. SELECT collectionTime, generateUUIDv4(), * FROM eso.DATA_esoCEF_L limit 500000
   see 1 Superset without sleep 500k rows 2sec.xlsx

• I can not see that query in system.processes because it shows that query running very quickly with 2 seconds which is impossible. In Superset I waited for 1min45sec. Of course it takes a lot of time to rendering data.

2. SELECT sleep(1), collectionTime, generateUUIDv4(), * FROM eso.DATA_esoCEF_L limit 500000
   see 2 Superset with sleep 500k rows 56sec.xlsx

• I can see that query in system.processes. Actually it shoud be slower for 1 sec additionally to first query. But it shows that query rinning for 56sec.

DBeaver:

3. SELECT collectionTime, generateUUIDv4(), * FROM eso.DATA_esoCEF_L limit 200000
   see 3 Beaver without sleep 200k rows 11sec.xlsx

4. SELECT sleep(1), collectionTime, generateUUIDv4(), * FROM eso.DATA_esoCEF_L limit 50000
   see 4 Beaver with sleep 50k rows 24sec.xlsx

[den-crane]

hint: I am not going to look into xlsx files. Too cumbersome. The last time i used MS. Excel was 1996.

[berlicon]

1 Superset without sleep 500k rows 2sec.csv
2 Superset with sleep 500k rows 56sec.csv
3 Beaver without sleep 200k rows 11sec.csv
4 Beaver with sleep 50k rows 24sec.csv

[den-crane]

I don't see anything new.

A query (without sleep) from the Superset is fast.
Superset uses Native format and has http compression enabled. It just quickly fetches the result.
Unclear why RealTime is so inflated.

query	user_agent	query_durationS	RealTimeS	UserTimeS	Settings
SELECT collectionTime, generateUUIDv4(), * FROM eso.DATA_esoCEF_L limit 500001 FORMAT Native	superset	1.724	8.441	2.889	enable_http_compression=1
SELECT sleep(1), collectionTime, generateUUIDv4(), * FROM eso.DATA_esoCEF_L limit 500001 FORMAT Native	superset	56.182	272.583	3.088	enable_http_compression=1
SELECT collectionTime, generateUUIDv4(), * FROM eso.DATA_esoCEF_L limit 200000	DBeaver	11.479	70.085	2.536
SELECT sleep(1), collectionTime, generateUUIDv4(), * FROM eso.DATA_esoCEF_L limit 50000	DBeaver	24.285	47.84	0.781