max_query_time is not working correctly

[thehixz]

Describe the bug
Seems like option max_query_time is not working at all.
If I understand correcly, this query should fail immediately, but is is running for 27 sec:

> select * from main where source='foo' option max_query_time=1;
Empty set, 1 warning (27.19 sec)

main is a distributed index, source - string attribute, which exists in all child indices.

It fails for single rt index too:

mysql> select * from person where source='foo' option max_query_time=1;
Empty set, 1 warning (20.80 sec)

mysql> show warnings;
+---------+------+--------------------------------------------------+
| Level   | Code | Message                                          |
+---------+------+--------------------------------------------------+
| warning | 1000 | index person: query time exceeded max_query_time |
+---------+------+--------------------------------------------------+

Expected behavior
max_query_time should limit query execution time.

Describe the environment:

• manticoresearch/manticore:5.0.2 docker image, with no MCL enabled

Additional context

mysql> show create table person;

+--------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table  | Create Table                                                                                                                                                                                                                                                                                                                                                                                                                                                               |
+--------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| person | CREATE TABLE person (
is_deleted bool,
entity_id string attribute,
schema string attribute,
source string attribute,
attributes json,
name text indexed,
notes text indexed,
email text indexed,
phone text indexed,
address text indexed
) min_infix_len='2' index_exact_words='1' min_word_len='2' morphology='stem_ru' min_stemming_len='3' expand_keywords='1' |
+--------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.02 sec)

mysql> show table person status;

Note max_sec here is always <= 5 sec.

+-----------------------------+-----------------------------------------------------------------------------------------------------------+
| Variable_name               | Value                                                                                                     |
+-----------------------------+-----------------------------------------------------------------------------------------------------------+
| index_type                  | rt                                                                                                        |
| indexed_documents           | 319606742                                                                                                 |
| indexed_bytes               | 129743821186                                                                                              |
| ram_bytes                   | 2364497880                                                                                                |
| disk_bytes                  | 105628651821                                                                                              |
| disk_mapped                 | 67991691245                                                                                               |
| disk_mapped_cached          | 2359066624                                                                                                |
| disk_mapped_doclists        | 0                                                                                                         |
| disk_mapped_cached_doclists | 0                                                                                                         |
| disk_mapped_hitlists        | 0                                                                                                         |
| disk_mapped_cached_hitlists | 0                                                                                                         |
| killed_documents            | 0                                                                                                         |
| killed_rate                 | 0.00%                                                                                                     |
| ram_chunk                   | 5327592                                                                                                   |
| ram_chunk_segments_count    | 13                                                                                                        |
| disk_chunks                 | 24                                                                                                        |
| mem_limit                   | 134217728                                                                                                 |
| mem_limit_rate              | 95.00%                                                                                                    |
| ram_bytes_retired           | 0                                                                                                         |
| tid                         | 1559084                                                                                                   |
| tid_saved                   | 1559084                                                                                                   |
| query_time_1min             | {"queries":60, "avg_sec":0.004, "min_sec":0.000, "max_sec":0.065, "pct95_sec":0.030, "pct99_sec":0.030}   |
| query_time_5min             | {"queries":80, "avg_sec":0.004, "min_sec":0.000, "max_sec":0.065, "pct95_sec":0.030, "pct99_sec":0.031}   |
| query_time_15min            | {"queries":137, "avg_sec":0.003, "min_sec":0.000, "max_sec":0.073, "pct95_sec":0.031, "pct99_sec":0.073}  |
| query_time_total            | {"queries":7354, "avg_sec":0.019, "min_sec":0.000, "max_sec":4.976, "pct95_sec":0.081, "pct99_sec":0.357} |
| found_rows_1min             | {"queries":60, "avg":2, "min":1, "max":18, "pct95":18, "pct99":18}                                        |
| found_rows_5min             | {"queries":80, "avg":8, "min":1, "max":183, "pct95":38, "pct99":183}                                      |
| found_rows_15min            | {"queries":137, "avg":6, "min":0, "max":183, "pct95":38, "pct99":183}                                     |
| found_rows_total            | {"queries":7354, "avg":14913, "min":0, "max":10122055, "pct95":66, "pct99":10489}                         |
+-----------------------------+-----------------------------------------------------------------------------------------------------------+
29 rows in set (0.66 sec)

set profiling=1; select * from person where source='foo' option max_query_time=1; show profile;

Query OK, 0 rows affected (0.00 sec)

Empty set, 1 warning (20.39 sec)

+--------------+------------+----------+---------+
| Status       | Duration   | Switches | Percent |
+--------------+------------+----------+---------+
| unknown      | 0.000066   | 6        | 0.00    |
| local_search | 0.000267   | 2        | 0.00    |
| sql_parse    | 0.000033   | 1        | 0.00    |
| setup_iter   | 217.523436 | 12       | 96.59   |
| fullscan     | 0.000450   | 1        | 0.00    |
| dict_setup   | 0.000001   | 1        | 0.00    |
| parse        | 0.000001   | 1        | 0.00    |
| init         | 0.000040   | 4        | 0.00    |
| finalize     | 7.689642   | 1        | 3.41    |
| clone_attrs  | 0.000034   | 1        | 0.00    |
| aggregate    | 0.000489   | 1        | 0.00    |
| net_write    | 0.000053   | 2        | 0.00    |
| total        | 225.214512 | 33       | 0       |
+--------------+------------+----------+---------+
13 rows in set (0.00 sec)

[thehixz]

It works properly when running query without where constraints, but with facets:

For rt table:

mysql> select * from person option max_query_time=5000 facet source limit 100 facet schema limit 100 facet is_deleted limit 100;
66 rows in set (5.01 sec)

For distributed table still worse than expected, but still better than was:

79 rows in set (11.34 sec)

Profilling a query shows this:

+-----------+----------+----------+---------+
| Status    | Duration | Switches | Percent |
+-----------+----------+----------+---------+
| unknown   | 5.005272 | 3        | 100.00  |
| sql_parse | 0.000194 | 1        | 0.00    |
| net_write | 0.000045 | 1        | 0.00    |
| total     | 5.005511 | 5        | 0       |
+-----------+----------+----------+---------+

[thehixz]

There are also a significant lag for any status queries during this select.

Time is lower for distributed index:

mysql> show status;
56 rows in set (0.27 sec)

mysql> show threads;
12 rows in set (1.38 sec)

And is enormous while selecting a single rt index:

mysql> show status;
56 rows in set (15.91 sec)

mysql> show threads;
12 rows in set (12.14 sec)

[thehixz]

Also when running query on these index, top reports 15-25 iowait.

I've played around with threads and pseudo_sharding (didnt help), and noticed, that even with pseudo_sharding=0 I see all my 12 cores processing the same index.

Maybe this will be related.

[tomatolog]

for distributed table max_query_time does not work but agent_query_timeout option take place and that was fixed in recent master.

For the RT index it depends on amount of disk chunks and could not exceed some minimum value depends on setup time for every disk chunk.

It could be better to retest your case with the master version to make sure that some points are fixed in the current version.

[thehixz]

@tomatolog

Still, query with facet on source stops at exactly 5.00s for rt and ~6-7s for distributed index. So I guess problem is in handling timeouts with where constraints, not in config/timing issues?

agent_query_timeout option take place

Seems like it's not working either on 5.0.2:

mysql> select * from main where source='foo' option agent_query_timeout=5000 option max_query_time=5000
Empty set (55.22 sec)

It could be better to retest your case with the master version to make sure that some points are fixed in the current version.

Will latest docker image do the trick?

[tomatolog]

the manticoresearch/manticore:dev is the latest dev docker image

[tomatolog]

manticoresearch/manticore:latest is the latest release however fix of agent_query_timeout was done yesterday

[tomatolog]

looking at profiler you provided I see that most of time goes into setup_iter but check of the max_query_time goes at the fullscan stage for full scan queries - that is why it could take some time to setup some structures for RT index with 24 disk chunks.

However I'd check current master \ manticoresearch/manticore:dev to make sure that some points got fixed and if some of there still do not work as expected investigated only these points.

[thehixz]

Thank you very much @tomatolog

Works as expected on version 6.2.13 3a0507aee@230907 dev (docker :dev) and 6.2.12 dc5144d35@230822 (:latest).

The only question left: any estimate when this versions will become stable so we could use them in prod?

mysql> set profiling=1; select * from person where source='foo' option max_query_time=5000; show profile;
Query OK, 0 rows affected (0.00 sec)

Empty set, 1 warning (5.01 sec)

+--------------+-----------+----------+---------+
| Status       | Duration  | Switches | Percent |
+--------------+-----------+----------+---------+
| unknown      | 0.000101  | 6        | 0.00    |
| local_search | 0.012581  | 2        | 0.02    |
| sql_parse    | 0.000072  | 1        | 0.00    |
| setup_iter   | 0.000193  | 12       | 0.00    |
| fullscan     | 60.010115 | 13       | 99.97   |
| dict_setup   | 0.000006  | 1        | 0.00    |
| parse        | 0.000001  | 1        | 0.00    |
| init         | 0.000341  | 4        | 0.00    |
| finalize     | 0.002097  | 1        | 0.00    |
| clone_attrs  | 0.000019  | 1        | 0.00    |
| aggregate    | 0.000022  | 1        | 0.00    |
| net_write    | 0.000045  | 2        | 0.00    |
| total        | 60.025593 | 45       | 0       |
+--------------+-----------+----------+---------+
13 rows in set (0.00 sec)

[sanikolaev]

6.2.12 is considered stable, it's the latest release - https://manual.manticoresearch.com/Changelog#Version-6.2.12

There's nothing more stable at the moment: the nightly build might have a few fixes, but it also has a few improvements that may be a source of unknown yet bugs. 6.2.12 is a maintenenance release with 12 bug fixes made after the release of 6.2.0 which in its turn was tested in a large Manticore installation for a few weeks before releasing.

[tomatolog]

6.2.12 is a stable release that you could use the only related fix at the 6.2.13 is 5d71ccb without that fix 6.2.12 release does not take into account per index agent_query_timeout option, ie always took default or user defined agent_query_timeout from the query or searchd.agent_query_timeout

You could try 6.2.12 and if the issue do not affect you or all you cases work well use that release