1

On our server running MariaDB 10.1 (the latest Debian package), with low load (load average: 0.79, 0.88, 1.00), I often receive error message that "Prepared statement needs to be re-prepared".

It is difficult to reproduce, it appears randomly, approximately 40-50 times per day.

I have read documentation about repreparation, where is the following explanation for repreparation:

Repreparation occurs after DDL statements such as those that create, drop, alter, rename, or truncate tables, or that analyze, optimize, or repair tables. Repreparation also occurs after referenced tables or views are flushed from the table definition cache, either implicitly to make room for new entries in the cache, or explicitly due to FLUSH TABLES.

I'm not aware of any DDL statements running on the server. Our application does not use "FLUSH TABLES". Except our application only internally used Phabricator is running (used by 8 devs) and two other minimally visited applications written in PHP using MariaDB. Here are command statistics: enter image description here

Do you have any idea, how to find the cause for repreparation? I don't want to blindly increase table_definition_cache (currently 400) or table_open_cache (2000). Or do you think it is to small and it is safe to increase?

For debugging info: SHOW GLOBAL STATUS, SHOW VARIABLES and memory info from the server.

  • "Repreparation also occurs after referenced tables or views are flushed from the table definition cache, **either implicitly **" -- implicitly, automatically in the background – Philᵀᴹ Jul 30 '18 at 13:39
  • But what can be the reason? In our case, it tries to repreparate 3 times and then gives up with the error message. Quoting documentation: "The server attempts repreparation up to three times. An error occurs if all attempts fail." Why it fails in our case so often? – oneee Jul 30 '18 at 15:46
  • @Philᵀᴹ was trying to illustrate that the tables are being likely being evicted from the cache organically. When the cache gets full MySQL/MariaDB will release tables from the cache and may need to reopen them at a later stage. dev.mysql.com/doc/refman/5.7/en/table-cache.html You may see better results if you increase the table cache size. It's a dynamic change and simple to roll back if your tests yield unexpected results. – eroomydna Jul 30 '18 at 22:29
  • I don't get it:-/ It tries the first time to prepare statement. Boom - cache was cleared. It tries the second time. And again - the cache was cleared? And then finally the third time - and once again it was cleared. Why is table cache cleared 3 times? Or it does not rebuild the cache between those 3 retries? Or am I missing something? – oneee Jul 31 '18 at 20:47
  • Here are command statistics:. What tool this screenshot is from? Thanks – Ivanov Aug 3 '18 at 6:43
0

From the 5.1.25 Changelog:

Metadata changes to tables or views referred to by prepared statements are detected and cause automatic repreparation of the statement when it is next executed. The server attempts repreparation up to three times. An error occurs if all attempts fail. Metadata changes occur for DDL statements such as those that create, drop, alter, rename, or truncate tables, or that analyze, optimize, or repair tables. Repreparation also occurs after referenced tables or views are flushed from the table definition cache, either implicitly to make room for new entries in the cache, or explicitly due to FLUSH TABLES. The default value of the table_definition_cache system variable has been increased from 128 to 256. The purpose of this increase is to lessen the chance that prepared statements will need repreparation due to referred-to tables/views having been flushed from the cache to make room for new entries.

So...

  • Com_alter_table = 2496 = 3.5/hour -- This is rather high, and could cause the need for reprepare.
  • CREATE/DROP TABLE are also rather frequent.
  • I suggest increasing table_definition_cache.

Further analysis...

Observations:

  • Version: 10.1.26-MariaDB-0+deb9u1
  • 64 GB of RAM
  • Uptime = 30d 00:53:13
  • You are not running on Windows.
  • Running 64-bit version
  • It appears that you are running both MyISAM and InnoDB.

The More Important Issues:

innodb_buffer_pool_size = 50G   -- from 1G
     -- Or the dataset size, if significantly less than that.
table_open_cache = 3000
innodb_open_files = 3000
table_definition_cache = 800
join_buffer_size = 1M
query_cache_size = 32M
max_connections = 200  -- Currently 151, and you ran out of connections some time
thread_cache_size = 30

Convert the rest from MyISAM to InnoDB

USE dbname and several SHOWs occur awfully often; what is going on?

A lot of slow queries, table scans, etc. Look for the slowest few queries and work on improving them: http://mysql.rjweb.org/doc.php/mysql_analysis#slow_queries_and_slowlog

Did you deliberately turn off some of the optimizer_switches? If so, why?

Details and other observations:

( innodb_buffer_pool_size / _ram ) = 1024M / 65536M = 1.6% -- % of RAM used for InnoDB buffer_pool

( (key_buffer_size / 0.20 + innodb_buffer_pool_size / 0.70) / _ram ) = (16M / 0.20 + 1024M / 0.70) / 65536M = 2.4% -- Most of available ram should be made available for caching. -- http://mysql.rjweb.org/doc.php/memory

( Opened_tables ) = 6,996,394 / 2595193 = 2.7 /sec -- Frequency of opening Tables -- increase table_open_cache

( Opened_table_definitions ) = 5,643,679 / 2595193 = 2.2 /sec -- Frequency of opening .frm files -- Increase table_definition_cache and/or table_open_cache.

( innodb_buffer_pool_size ) = 1024M -- InnoDB Data + Index cache -- woefully small.

( default_tmp_storage_engine ) = default_tmp_storage_engine =

( innodb_print_all_deadlocks ) = innodb_print_all_deadlocks = OFF -- Whether to log all Deadlocks. -- If you are plagued with Deadlocks, turn this on. Caution: If you have lots of deadlocks, this may write a lot to disk.

( join_buffer_size / _ram ) = 262,144 / 65536M = 0.00% -- 0-N per thread. May speed up JOINs (better to fix queries/indexes) (all engines) Used for index scan, range index scan, full table scan, each full JOIN, etc. -- If large, decrease join_buffer_size to avoid memory pressure. Suggest less than 1% of RAM. If small, increase to 0.01% of RAM to improve some queries.

( query_prealloc_size / _ram ) = 24,576 / 65536M = 0.00% -- For parsing. Pct of RAM

( query_alloc_block_size / _ram ) = 16,384 / 65536M = 0.00% -- For parsing. Pct of RAM

( local_infile ) = local_infile = ON -- local_infile = ON is a potential security issue

( Qcache_lowmem_prunes ) = 54,439,645 / 2595193 = 21 /sec -- Running out of room in QC -- increase query_cache_size

( Qcache_lowmem_prunes/Qcache_inserts ) = 54,439,645/193592210 = 28.1% -- Removal Ratio (pct of time need to prune)

( Qcache_hits / Qcache_inserts ) = 194,941,934 / 193592210 = 1.01 -- Hit to insert ratio -- high is good -- Consider turning off the query cache.

( (query_cache_size - Qcache_free_memory) / Qcache_queries_in_cache / query_alloc_block_size ) = (16M - 2696464) / 7979 / 16384 = 0.108 -- query_alloc_block_size vs formula -- Adjust query_alloc_block_size

( Created_tmp_disk_tables ) = 13,897,242 / 2595193 = 5.4 /sec -- Frequency of creating disk "temp" tables as part of complex SELECTs -- increase tmp_table_size and max_heap_table_size. Check the rules for temp tables on when MEMORY is used instead of MyISAM. Perhaps minor schema or query changes can avoid MyISAM. Better indexes and reformulation of queries are more likely to help.

( Select_scan ) = 168,942,798 / 2595193 = 65 /sec -- full table scans -- Add indexes / optimize queries (unless they are tiny tables)

( Select_scan / Com_select ) = 168,942,798 / 402363586 = 42.0% -- % of selects doing full table scan. (May be fooled by Stored Routines.) -- Add indexes / optimize queries

( binlog_format ) = binlog_format = STATEMENT -- STATEMENT/ROW/MIXED. ROW is preferred; it may become the default.

( Slow_queries ) = 169,941,950 / 2595193 = 65 /sec -- Frequency (Slow queries per sec) -- Rework slow guys; improve indexes; watch disk space for slow log file

( Slow_queries / Questions ) = 169,941,950 / 712388796 = 23.9% -- Frequency (% of all queries) -- Find slow queries; check indexes.

( Subquery_cache_hit / ( Subquery_cache_hit + Subquery_cache_miss ) ) = 1,016,245 / ( 1016245 + 217503779 ) = 0.47% -- Subquery cache hit rate -- Consider SET optimizer_switch='subquery_cache=off';

( log_queries_not_using_indexes ) = log_queries_not_using_indexes = ON -- Whether to include such in slowlog. -- This clutters the slowlog; turn it off so you can see the real slow queries.

( back_log / max_connections ) = 80 / 151 = 53.0%

( Max_used_connections / max_connections ) = 152 / 151 = 100.7% -- Peak % of connections -- increase max_connections and/or decrease wait_timeout

( Com_change_db / Connections ) = 245,625,094 / 14750877 = 16.7 -- Database switches per connection -- (minor) Consider using "db.table" syntax

( Com_change_db ) = 245,625,094 / 2595193 = 95 /sec -- Probably comes from USE statements. -- Consider connecting with DB, using db.tbl syntax, eliminating spurious USE statements, etc.

( Connections ) = 14,750,877 / 2595193 = 5.7 /sec -- Connections -- Increase wait_timeout; use pooling?

( Threads_created / Connections ) = 1,856,073 / 14750877 = 12.6% -- Rapidity of process creation -- Increase thread_cache_size

Abnormally large:

Com_savepoint = 5.9 /HR
Com_show_create_table = 0.31 /sec
Com_show_events = 14 /HR
Com_show_function_status = 14 /HR
Com_show_procedure_status = 14 /HR
Com_show_tables = 2.4 /sec
Com_stmt_close = 139 /sec
Com_stmt_execute = 139 /sec
Com_stmt_prepare = 139 /sec
Com_stmt_reprepare = 0.24 /sec
Com_unlock_tables = 43 /HR
Feature_fulltext = 54 /HR
Feature_subquery = 24 /sec
Handler_discover = 0.072 /HR
Handler_read_rnd_deleted = 62 /sec
Handler_savepoint = 5.9 /HR
Sort_priority_queue_sorts = 137 /sec
Sort_range = 86 /sec
Sort_scan = 57 /sec
Subquery_cache_miss = 84 /sec
innodb_max_dirty_pages_pct_lwm = 0.10%

Abnormal strings:

innodb_cleaner_lsn_age_factor = HIGH_CHECKPOINT
innodb_empty_free_list_algorithm = BACKOFF
innodb_fast_shutdown = 1
innodb_foreground_preflush = EXPONENTIAL_BACKOFF
innodb_log_checksum_algorithm = INNODB
myisam_stats_method = NULLS_UNEQUAL
opt_s__engine_condition_pushdown = off
opt_s__mrr = off
opt_s__mrr_cost_based = off
  • Found the issue, and added to the start of my answer. – Rick James Aug 20 '18 at 3:29
  • Thanks. How do I find those frequent "CREATE/DROP TABLE" statements? There are several applications using MariaDB, so it is hard to look at so many source code files. Also, "USE dbname and several SHOWs occur awfully often" - how to find where? If I see whole command with dbname, I can track it. – oneee Aug 31 '18 at 19:48
  • @oneee - The "general log" will capture all statements. Caution: this will quickly fill up disk, so turn it off pretty fast. The "slow log" is another option. – Rick James Sep 3 '18 at 4:19

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.