Assertion `thd->utime_after_query >= thd->utime_after_lock' failed in query_response_time_audit_notify on 2nd execution of SP with query cache

INSTALL SONAME 'query_response_time';

SET @qct = @@global.query_cache_type;

SET GLOBAL query_cache_type=ON;

SET query_response_time_session_stats=ON, query_cache_type=ON;

CREATE TABLE t (a INT);

CREATE PROCEDURE sp() EXECUTE IMMEDIATE 'SELECT * FROM t';

CALL sp;

CALL sp;

DROP TABLE t;

DROP PROCEDURE sp;

SET GLOBAL query_cache_type= @qct;

UNINSTALL SONAME 'query_response_time';

mariadbd: /data/bld/11.8-asan-ubsan/plugin/query_response_time/plugin.cc:246: void query_response_time_audit_notify(THD*, unsigned int, const void*): Assertion `thd->utime_after_query >= thd->utime_after_lock' failed.

260120 12:01:34 [ERROR] /share8t/bld/11.8-asan-ubsan/sql/mariadbd got signal 6 ;

#10 0x00007f3002853eb2 in __GI___assert_fail (assertion=0x7f2ff588e7c0 "thd->utime_after_query >= thd->utime_after_lock", file=0x7f2ff588e6a0 "/data/bld/11.8-asan-ubsan/plugin/query_response_time/plugin.cc", line=246, function=0x7f2ff588e700 "void query_response_time_audit_notify(THD*, unsigned int, const void*)") at ./assert/assert.c:101

#11 0x00007f2ff588a979 in query_response_time_audit_notify (thd=0x62c0000b0218, event_class=<optimized out>, event=<optimized out>) at /data/bld/11.8-asan-ubsan/plugin/query_response_time/plugin.cc:246

#12 0x0000561df0eeb2e0 in plugins_dispatch (thd=thd@entry=0x62c0000b0218, plugin=<optimized out>, arg=arg@entry=0x7f2ff68e6490) at /data/bld/11.8-asan-ubsan/sql/sql_audit.cc:398

#13 0x0000561df0eed7b6 in mysql_audit_notify (thd=thd@entry=0x62c0000b0218, event_class=event_class@entry=0, event=event@entry=0x7f2ff68e65a0) at /data/bld/11.8-asan-ubsan/sql/sql_audit.cc:437

#14 0x0000561df074e2a3 in mysql_audit_general (thd=0x62c0000b0218, event_subtype=event_subtype@entry=3, error_code=error_code@entry=0, msg=msg@entry=0x561df41ebbe0 "Query") at /data/bld/11.8-asan-ubsan/sql/sql_audit.h:194

#15 0x0000561df0788b39 in Prepared_statement::execute (this=this@entry=0x61900005be98, expanded_query=expanded_query@entry=0x7f2ff68e6d70, open_cursor=open_cursor@entry=false) at /data/bld/11.8-asan-ubsan/sql/sql_prepare.cc:5131

#16 0x0000561df079a99d in Prepared_statement::execute_loop (this=this@entry=0x61900005be98, expanded_query=expanded_query@entry=0x7f2ff68e6d70, open_cursor=open_cursor@entry=false, packet=packet@entry=0x0, packet_end=packet_end@entry=0x0) at /data/bld/11.8-asan-ubsan/sql/sql_prepare.cc:4461

#17 0x0000561df079e0b8 in Prepared_statement::execute_immediate (this=this@entry=0x61900005be98, query=<optimized out>, query_len=<optimized out>) at /data/bld/11.8-asan-ubsan/sql/sql_prepare.cc:5253

#18 0x0000561df079ecc6 in mysql_sql_stmt_execute_immediate (thd=thd@entry=0x62c0000b0218) at /data/bld/11.8-asan-ubsan/sql/sql_prepare.cc:2870

#19 0x0000561df067cfc5 in mysql_execute_command (thd=0x62c0000b0218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/bld/11.8-asan-ubsan/sql/sql_parse.cc:3997

#20 0x0000561df12e278e in sp_instr_stmt::exec_core (this=0x625000240260, thd=<optimized out>, nextp=0x7f2ff68e8600) at /data/bld/11.8-asan-ubsan/sql/sp_instr.cc:1182

#21 0x0000561df12f7e6d in sp_lex_keeper::reset_lex_and_exec_core (this=this@entry=0x625000240298, thd=thd@entry=0x62c0000b0218, nextp=nextp@entry=0x7f2ff68e8600, open_tables=open_tables@entry=false, instr=instr@entry=0x625000240260, rerun_the_same_instr=rerun_the_same_instr@entry=false) at /data/bld/11.8-asan-ubsan/sql/sp_instr.cc:350

#22 0x0000561df1305420 in sp_lex_keeper::validate_lex_and_exec_core (this=this@entry=0x625000240298, thd=thd@entry=0x62c0000b0218, nextp=nextp@entry=0x7f2ff68e8600, open_tables=open_tables@entry=false, instr=instr@entry=0x625000240260) at /data/bld/11.8-asan-ubsan/sql/sp_instr.cc:529

#23 0x0000561df1308182 in sp_instr_stmt::execute (this=0x625000240260, thd=0x62c0000b0218, nextp=<optimized out>) at /data/bld/11.8-asan-ubsan/sql/sp_instr.cc:1084

#24 0x0000561df01805c4 in sp_head::execute (this=this@entry=0x62500023f198, thd=thd@entry=0x62c0000b0218, merge_da_on_success=merge_da_on_success@entry=true) at /data/bld/11.8-asan-ubsan/sql/sp_head.cc:1290

#25 0x0000561df0189ae5 in sp_head::execute_procedure (this=this@entry=0x62500023f198, thd=thd@entry=0x62c0000b0218, args=args@entry=0x62c0000b56f0) at /data/bld/11.8-asan-ubsan/sql/sp_head.cc:2316

#26 0x0000561df063943b in do_execute_sp (thd=thd@entry=0x62c0000b0218, sp=sp@entry=0x62500023f198) at /data/bld/11.8-asan-ubsan/sql/sql_parse.cc:3097

#27 0x0000561df0651e78 in Sql_cmd_call::execute (this=<optimized out>, thd=0x62c0000b0218) at /data/bld/11.8-asan-ubsan/sql/sql_parse.cc:3320

#28 0x0000561df069738e in mysql_execute_command (thd=thd@entry=0x62c0000b0218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/bld/11.8-asan-ubsan/sql/sql_parse.cc:5924

#29 0x0000561df069bfbf in mysql_parse (thd=thd@entry=0x62c0000b0218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f2ff68eaa20) at /data/bld/11.8-asan-ubsan/sql/sql_parse.cc:7953

#30 0x0000561df06a53ae in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62c0000b0218, packet=packet@entry=0x629000253219 "CALL sp", packet_length=packet_length@entry=7, blocking=blocking@entry=true) at /data/bld/11.8-asan-ubsan/sql/sql_parse.cc:1921

#31 0x0000561df06b2384 in do_command (thd=thd@entry=0x62c0000b0218, blocking=blocking@entry=true) at /data/bld/11.8-asan-ubsan/sql/sql_parse.cc:1431

#32 0x0000561df0efe566 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x6080000039b8, put_in_cache=put_in_cache@entry=true) at /data/bld/11.8-asan-ubsan/sql/sql_connect.cc:1504

#33 0x0000561df0eff6cf in handle_one_connection (arg=0x6080000039b8) at /data/bld/11.8-asan-ubsan/sql/sql_connect.cc:1416

#34 0x0000561df29cd6d6 in pfs_spawn_thread (arg=0x617000005b98) at /data/bld/11.8-asan-ubsan/storage/perfschema/pfs.cc:2198

#35 0x00007f30028a81c4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442

#36 0x00007f300292885c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

commit c1fcedf443aa21ef626cd409d62b448a69858c81

Merge: eea493463bc ab2e0d4f0d2

Author: Sergei Golubchik

Date:   Mon Jan 5 18:19:14 2026 +0100

    Merge branch '11.4' into 11.8

commit 317fb109153b45091003f0b1380b5d68522fce29

Author:     Sergei Golubchik

AuthorDate: Sat Dec 27 11:35:01 2025 +0100

    MDEV-38375 do MYSQL_AUDIT_GENERAL_STATUS on ps execute too

    just like slow logging, MYSQL_AUDIT_GENERAL_STATUS

    should be done inside Prepared_statement::execute()