[MDEV-23936] Wrong (negative) values in P_S memory summary tables Created: 2020-10-11  Updated: 2023-03-17

Status: Open
Project: MariaDB Server
Component/s: Performance Schema
Affects Version/s: 10.5.7
Fix Version/s: 10.5

Type: Bug Priority: Major
Reporter: Valerii Kravchuk Assignee: Sergei Golubchik
Resolution: Unresolved Votes: 2
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-25250 performance schema shows negative amo... Closed

 Description   

If we start MariaDB 10.5 with Performance Schema and all memory instrumentation enabled:

openxs@ao756:~/dbs/maria10.5$ bin/mysqld_safe --no-defaults --port=3311 --socket=/tmp/mariadb105.sock --performance_schema=1  --performance-schema-instrument='memory/%=ON' &
 
[1] 14916
 
openxs@ao756:~/dbs/maria10.5$ 201011 13:51:40 mysqld_safe Logging to '/home/openxs/dbs/maria10.5/data/ao756.err'.
 
201011 13:51:41 mysqld_safe Starting mariadbd daemon with databases from /home/openxs/dbs/maria10.5/data

we can see negative values reported immediately after startup for memory/innodb/std event:

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock performance_schema
 
Reading table information for completion of table and column names
 
You can turn off this feature to get a quicker startup with -A
 
 
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
 
Your MariaDB connection id is 3
 
Server version: 10.5.7-MariaDB Source distribution
 
 
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
 
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
 
 
MariaDB [performance_schema]> select * from memory_summary_by_thread_by_event_name where current_number_of_bytes_used <0\G
 
*************************** 1. row ***************************
 
                   THREAD_ID: 7
 
                  EVENT_NAME: memory/innodb/std
 
                 COUNT_ALLOC: 5
 
                  COUNT_FREE: 29
 
   SUM_NUMBER_OF_BYTES_ALLOC: 728
 
    SUM_NUMBER_OF_BYTES_FREE: 1496
 
              LOW_COUNT_USED: -24
 
          CURRENT_COUNT_USED: -24
 
             HIGH_COUNT_USED: 1
 
    LOW_NUMBER_OF_BYTES_USED: -768
 
CURRENT_NUMBER_OF_BYTES_USED: -768
 
   HIGH_NUMBER_OF_BYTES_USED: 32
 
1 row in set (0,004 sec)
 
 
 
MariaDB [performance_schema]> select t.*, m.* from memory_summary_by_thread_by_event_name m join threads t on m.thread_id = t.thread_id where current_number_of_bytes_used <0\G
 
*************************** 1. row ***************************
 
                   THREAD_ID: 7
 
                        NAME: thread/innodb/thread_pool_thread
 
                        TYPE: BACKGROUND
 
              PROCESSLIST_ID: NULL
 
            PROCESSLIST_USER: NULL
 
            PROCESSLIST_HOST: NULL
 
              PROCESSLIST_DB: NULL
 
         PROCESSLIST_COMMAND: NULL
 
            PROCESSLIST_TIME: NULL
 
           PROCESSLIST_STATE: NULL
 
            PROCESSLIST_INFO: NULL
 
            PARENT_THREAD_ID: NULL
 
                        ROLE: NULL
 
                INSTRUMENTED: YES
 
                     HISTORY: YES
 
             CONNECTION_TYPE: Error
 
                THREAD_OS_ID: 15007
 
                   THREAD_ID: 7
 
                  EVENT_NAME: memory/innodb/std
 
                 COUNT_ALLOC: 5
 
                  COUNT_FREE: 29
 
   SUM_NUMBER_OF_BYTES_ALLOC: 728
 
    SUM_NUMBER_OF_BYTES_FREE: 1496
 
              LOW_COUNT_USED: -24
 
          CURRENT_COUNT_USED: -24
 
             HIGH_COUNT_USED: 1
 
    LOW_NUMBER_OF_BYTES_USED: -768
 
CURRENT_NUMBER_OF_BYTES_USED: -768
 
   HIGH_NUMBER_OF_BYTES_USED: 32
 
1 row in set (0,005 sec)

Negative values (or COUNT_FREE > COUNT_ALLOC) should never happen in this table. Either server does something wrong while getting the results, or there is a bug in instrumentation or we really free some memory that was not allocated.

I do not see such results from a similar test with MySQL 5.7.30 for example (no wonder, InnoDB implementation is very different and allocation is attributed to MariaDB's unique thread/innodb/thread_pool_thread background thread).

 Comments   
Comment by Valerii Kravchuk [ 2020-10-11 ]

After running sysbench test like this:

openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=4 --time=100 --mysql-socket=/tmp/mariadb105.sock --mysql-user=openxs --mysql-db=sbtest --report-interval=5 /usr/share/sysbench/oltp_update_index.lua run
 
sysbench 1.1.0-faaff4f (using bundled LuaJIT 2.1.0-beta3)
 
 
 
Running the test with following options:
 
Number of threads: 4
 
Report intermediate results every 5 second(s)
 
Initializing random number generator from current time
 
 
 
 
 
Initializing worker threads...
 
 
 
Threads started!
 
 
 
[ 5s ] thds: 4 tps: 100.44 qps: 100.44 (r/w/o: 0.00/100.44/0.00) lat (ms,95%): 77.19 err/s: 0.00 reconn/s: 0.00
 
[ 10s ] thds: 4 tps: 110.02 qps: 110.02 (r/w/o: 0.00/110.02/0.00) lat (ms,95%): 66.84 err/s: 0.00 reconn/s: 0.00
 
...

we can see that negative numbers increased, so the problem is not only with initialization stage, the results seem to be wrong all the time:

MariaDB [performance_schema]> select * from memory_summary_by_host_by_event_name where current_number_of_bytes_used <0\G                                        
*************************** 1. row ***************************
 
                        HOST: NULL
 
                  EVENT_NAME: memory/innodb/std
 
                 COUNT_ALLOC: 156
 
                  COUNT_FREE: 9540
 
   SUM_NUMBER_OF_BYTES_ALLOC: 17232
 
    SUM_NUMBER_OF_BYTES_FREE: 314048
 
              LOW_COUNT_USED: -9420
 
          CURRENT_COUNT_USED: -9384
 
             HIGH_COUNT_USED: 55
 
    LOW_NUMBER_OF_BYTES_USED: -301408
 
CURRENT_NUMBER_OF_BYTES_USED: -296816
 
   HIGH_NUMBER_OF_BYTES_USED: 7656
 
1 row in set (0,002 sec)

Comment by Vladislav Vaintroub [ 2021-03-25 ]

I closed MDEV-25250, but it has a reproducible (on Windows, or maybe generally with threadpool) negative memory display for global variables.

After normal startup "mysqld --performance_schema=1", and login, negative amount of memory is allocated by global_system_variables

mysql> select * from performance_schema.memory_summary_by_thread_by_event_name where count_free > count_alloc\G
 
*************************** 1. row ***************************
 
                   THREAD_ID: 1
 
                  EVENT_NAME: memory/sql/global_system_variables
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 2
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 128
 
              LOW_COUNT_USED: -2
 
          CURRENT_COUNT_USED: -2
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -128
 
CURRENT_NUMBER_OF_BYTES_USED: -128
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
1 row in set (0.01 sec)

Comment by Jaime Crespo [ 2022-06-22 ]

Also happening on 10.6.8 on Linux, thread pool and p_s enabled:

root@es2022[performance_schema]> select * from performance_schema.memory_summary_by_thread_by_event_name where count_free > count_alloc\G
 
*************************** 1. row ***************************
 
                   THREAD_ID: 1
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 1
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 152
 
              LOW_COUNT_USED: -1
 
          CURRENT_COUNT_USED: -1
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -152
 
CURRENT_NUMBER_OF_BYTES_USED: -152
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 2. row ***************************
 
                   THREAD_ID: 1
 
                  EVENT_NAME: memory/sql/global_system_variables
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 2
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 128
 
              LOW_COUNT_USED: -2
 
          CURRENT_COUNT_USED: -2
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -128
 
CURRENT_NUMBER_OF_BYTES_USED: -128
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 3. row ***************************
 
                   THREAD_ID: 12
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 39
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 10272
 
              LOW_COUNT_USED: -39
 
          CURRENT_COUNT_USED: -39
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -10272
 
CURRENT_NUMBER_OF_BYTES_USED: -10272
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 4. row ***************************
 
                   THREAD_ID: 13
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 12658595
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 1924106440
 
              LOW_COUNT_USED: -12658595
 
          CURRENT_COUNT_USED: -12658595
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -1924106440
 
CURRENT_NUMBER_OF_BYTES_USED: -1924106440
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 5. row ***************************
 
                   THREAD_ID: 29
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 327020
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 102815088
 
              LOW_COUNT_USED: -327020
 
          CURRENT_COUNT_USED: -327020
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -102815088
 
CURRENT_NUMBER_OF_BYTES_USED: -102815088
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 6. row ***************************
 
                   THREAD_ID: 42
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 328100
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 103154640
 
              LOW_COUNT_USED: -328100
 
          CURRENT_COUNT_USED: -328100
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -103154640
 
CURRENT_NUMBER_OF_BYTES_USED: -103154640
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 7. row ***************************
 
                   THREAD_ID: 53
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 326570
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 102673608
 
              LOW_COUNT_USED: -326570
 
          CURRENT_COUNT_USED: -326570
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -102673608
 
CURRENT_NUMBER_OF_BYTES_USED: -102673608
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 8. row ***************************
 
                   THREAD_ID: 224380
 
                  EVENT_NAME: memory/sql/sp_head::main_mem_root
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 3
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 448
 
              LOW_COUNT_USED: -3
 
          CURRENT_COUNT_USED: -3
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -448
 
CURRENT_NUMBER_OF_BYTES_USED: -448
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 9. row ***************************
 
                   THREAD_ID: 224380
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 5
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 3520
 
              LOW_COUNT_USED: -5
 
          CURRENT_COUNT_USED: -5
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -3520
 
CURRENT_NUMBER_OF_BYTES_USED: -3520
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 10. row ***************************
 
                   THREAD_ID: 224380
 
                  EVENT_NAME: memory/sql/user_var_entry
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 1264
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 102333440
 
              LOW_COUNT_USED: -1264
 
          CURRENT_COUNT_USED: -1264
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -102333440
 
CURRENT_NUMBER_OF_BYTES_USED: -102333440
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 11. row ***************************
 
                   THREAD_ID: 224246
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 1636
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 222890984
 
              LOW_COUNT_USED: -1636
 
          CURRENT_COUNT_USED: -1636
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -222890984
 
CURRENT_NUMBER_OF_BYTES_USED: -222890984
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
*************************** 12. row ***************************
 
                   THREAD_ID: 224248
 
                  EVENT_NAME: memory/sql/String::value
 
                 COUNT_ALLOC: 0
 
                  COUNT_FREE: 333
 
   SUM_NUMBER_OF_BYTES_ALLOC: 0
 
    SUM_NUMBER_OF_BYTES_FREE: 57240648
 
              LOW_COUNT_USED: -333
 
          CURRENT_COUNT_USED: -333
 
             HIGH_COUNT_USED: 0
 
    LOW_NUMBER_OF_BYTES_USED: -57240648
 
CURRENT_NUMBER_OF_BYTES_USED: -57240648
 
   HIGH_NUMBER_OF_BYTES_USED: 0
 
12 rows in set (0.022 sec)
 
 
 
root@es2022[performance_schema]> SELECT @@version;
 
+--------------------+
 
| @@version          |
 
+--------------------+
 
| 10.6.8-MariaDB-log |
 
+--------------------+
 
1 row in set (0.000 sec)

Comment by suresh ramagiri [ 2023-03-02 ]

One of our customers (10.5.16 ES MariaDB) also reported the issue of observing negative values for the columns in the p_s table - "performance_schema.memory_summary_by_thread_by_event_name"

They are trying to get the memory usage per thread at the database, and running below query, found negative values for the columns "CURRENT_COUNT_USED" and "CURRENT_NUMBER_OF_BYTES_USED"

 
 
MariaDB [xxxxx]> select mt.THREAD_ID AS thread_id
 
    ->        ,if(t.NAME = 'thread/sql/one_connection'
 
    ->        ,concat(t.PROCESSLIST_USER,'@',t.PROCESSLIST_HOST)
 
    ->        ,replace(t.NAME,'thread/','')) AS user
 
    ->        ,sum(mt.CURRENT_COUNT_USED) AS current_count_used
 
    ->        ,sum(mt.CURRENT_NUMBER_OF_BYTES_USED) AS current_allocated
 
    ->        ,ifnull(sum(mt.CURRENT_NUMBER_OF_BYTES_USED) / nullif(sum(mt.CURRENT_COUNT_USED),0),0) AS current_avg_alloc
 
    ->        ,max(mt.CURRENT_NUMBER_OF_BYTES_USED) AS current_max_alloc
 
    ->        ,sum(mt.SUM_NUMBER_OF_BYTES_ALLOC) AS total_allocated 
    ->   from (performance_schema.memory_summary_by_thread_by_event_name mt join performance_schema.threads t on(mt.THREAD_ID = t.THREAD_ID)) 
    ->  group by mt.THREAD_ID,if(t.NAME = 'thread/sql/one_connection',concat(t.PROCESSLIST_USER,'@',t.PROCESSLIST_HOST),replace(t.NAME,'thread/','')) 
    ->  order by sum(mt.CURRENT_NUMBER_OF_BYTES_USED) desc;
 
+-----------+----------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
 
| thread_id | user                       | current_count_used | current_allocated | current_avg_alloc | current_max_alloc | total_allocated |
 
+-----------+----------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
 
|        11 | sql/signal_handler         |                  0 |                 0 |            0.0000 |                 0 |               0 |
 
|       100 | innodb/thread_pool_thread  |                  0 |                 0 |            0.0000 |                 0 |               0 |
 
|         3 | aria/checkpoint_background |                  0 |                 0 |            0.0000 |                 0 |               0 |
 
|        10 | sql/binlog_background      |                  0 |                 0 |            0.0000 |                 0 |               0 |
 
|        12 | sql/manager                |                  0 |                 0 |            0.0000 |                 0 |               0 |
 
|        90 | maxscale_user@localhost    |                  0 |                 0 |            0.0000 |                 0 |               0 |
 
|         2 | mysys/statement_timer      |                  0 |                 0 |            0.0000 |                 0 |               0 |
 
|         4 | innodb/page_cleaner_thread |                  0 |                 0 |            0.0000 |                 0 |               0 |
 
|        14 | xxxx@localhost            |                -19 |             -5184 |          272.8421 |                 0 |               0 |
 
|         1 | sql/main                   |             -37826 |          -5749376 |          151.9953 |                 0 |               0 |
 
+-----------+----------------------------+--------------------+-------------------+-------------------+-------------------+-----------------+
 
10 rows in set (0.009 sec)

Generated at Thu Feb 08 09:26:11 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.