MySQL died after PHP send data to it.

[badoo]

MySQL died after PHP send data to it.

[alexanderilyin]

He is docker-compose.yml file which was used to start container:

version: '2'
services:
  pinba2:
    image: alexanderilyin/pinba2:fedora-25-v2.3.2
    container_name: pinba2
    restart: always
    ports:
      - "3002:3002/udp"
      - "3306:3306/tcp"
    build:
      context: .
      dockerfile: Dockerfile

[alexanderilyin]

Guys I've tried to rebuild it with your latest changes:

• alexanderilyin/pinba2@v2.3.2...master

After it, MySQL crashes on start:

root@example:~# docker ps -a --filter name=pinba
CONTAINER ID        IMAGE                          COMMAND                  CREATED             STATUS              PORTS                                            NAMES
c3f56f1deb2b        alexanderilyin/pinba2:latest   "/usr/local/bin/dock…"   3 minutes ago       Up 2 seconds        0.0.0.0:3002->3002/udp, 0.0.0.0:3306->3306/tcp   pinba2

Here is you you can reproduce it:

root@example:~# docker logs pinba2
+ '[' mysqld = mysqld ']'
+ ln -snf /usr/libexec/mysqld /usr/local/bin
+ rm -rf /etc/my.cnf.d/auth_gssapi.cnf
+ mysql_install_db --rpm
my_print_defaults: [ERROR] unknown option '--mysqld'
2018-11-30 22:53:24 140097611987264 [Note] /usr/libexec/mysqld (mysqld 10.1.26-MariaDB) starting as process 22 ...
2018-11-30 22:53:29 140485161457984 [Note] /usr/libexec/mysqld (mysqld 10.1.26-MariaDB) starting as process 51 ...
2018-11-30 22:53:32 139874367510848 [Note] /usr/libexec/mysqld (mysqld 10.1.26-MariaDB) starting as process 81 ...
PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
To do so, start the server, then issue the following commands:
'/usr/bin/mysqladmin' -u root password 'new-password'
'/usr/bin/mysqladmin' -u root -h c3f56f1deb2b password 'new-password'
Alternatively you can run:
'/usr/bin/mysql_secure_installation'
which will also give you the option of removing the test
databases and anonymous user created by default.  This is
strongly recommended for production servers.
See the MariaDB Knowledgebase at http://mariadb.com/kb or the
MySQL manual for more instructions.
Please report any problems at http://mariadb.org/jira
The latest information about MariaDB is available at http://mariadb.org/.
You can find additional information about the MySQL part at:
http://dev.mysql.com
Consider joining MariaDB's strong and vibrant community:
https://mariadb.org/get-involved/
+ chmod -R 777 /var/lib/mysql
+ pid=109
+ for i in '{10..0}'
+ mysqld --skip-networking -umysql
+ echo 'SELECT 1'
+ mysql
+ echo 'MySQL init process in progress...'
+ sleep 1
MySQL init process in progress...
2018-11-30 22:53:36 140433883003200 [Note] mysqld (mysqld 10.1.26-MariaDB) starting as process 109 ...
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: The InnoDB memory heap is disabled
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Using Linux native AIO
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Using SSE crc32 instructions
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Completed initialization of buffer pool
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Highest supported file format is Barracuda.
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: 128 rollback segment(s) are active.
2018-11-30 22:53:36 140433883003200 [Note] InnoDB: Waiting for purge to start
2018-11-30 22:53:36 140433883003200 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 1616819
2018-11-30 22:53:36 140433883003200 [Note] Plugin 'FEEDBACK' is disabled.
2018-11-30 22:53:36 140433095128832 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-11-30 22:53:36 140433883003200 [Note] mysqld: ready for connections.
Version: '10.1.26-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 0  MariaDB Server
+ for i in '{10..0}'
+ echo 'SELECT 1'
+ mysql
+ break
+ '[' 9 = 0 ']'
+ mysql --protocol=socket -uroot
+ mysql --protocol=socket -uroot
2018-11-30 22:53:37 109 [Note] PINBA: udp_reader; resolved 0.0.0.0:3002 -> 0.0.0.0:3002
2018-11-30 22:53:37 109 [Note] PINBA: engine initialized on 0.0.0.0:3002
+ kill -s TERM 109
+ wait 109
2018-11-30 22:53:37 140433881967360 [Note] mysqld: Normal shutdown
2018-11-30 22:53:37 140433881967360 [Note] Event Scheduler: Purging the queue. 0 events
2018-11-30 22:53:37 140433134966528 [Note] InnoDB: FTS optimize thread exiting.
2018-11-30 22:53:37 140433881967360 [Note] InnoDB: Starting shutdown...
2018-11-30 22:53:37 140433881967360 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-11-30 22:53:38 140433881967360 [Note] InnoDB: Shutdown completed; log sequence number 1616829
2018-11-30 22:53:38 109 [Note] PINBA: udp_reader/1; received shutdown request
2018-11-30 22:53:38 109 [Note] PINBA: udp_reader/0; received shutdown request
2018-11-30 22:53:38 140433881967360 [Note] mysqld: Shutdown complete
+ exec mysqld -umysql
2018-11-30 22:53:39 140583778556224 [Note] mysqld (mysqld 10.1.26-MariaDB) starting as process 1 ...
2018-11-30 22:53:39 1 [Note] PINBA: udp_reader; resolved 0.0.0.0:3002 -> 0.0.0.0:3002
2018-11-30 22:53:39 1 [Note] PINBA: engine initialized on 0.0.0.0:3002
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: The InnoDB memory heap is disabled
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Using Linux native AIO
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Using SSE crc32 instructions
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Completed initialization of buffer pool
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Highest supported file format is Barracuda.
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: 128 rollback segment(s) are active.
2018-11-30 22:53:39 140583778556224 [Note] InnoDB: Waiting for purge to start
2018-11-30 22:53:39 140583778556224 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 1616829
2018-11-30 22:53:39 140583778556224 [Note] Plugin 'FEEDBACK' is disabled.
2018-11-30 22:53:39 140582680786688 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-11-30 22:53:39 140583778556224 [Note] Server socket created on IP: '::'.
2018-11-30 22:53:39 140583778556224 [Note] mysqld: ready for connections.
Version: '10.1.26-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
181130 22:53:45 [ERROR] mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Server version: 10.1.26-MariaDB
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467133 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...

Here is used docker-compose.yml to reproduce:

version: '2'
services:
  pinba2:
    image: alexanderilyin/pinba2:latest
    container_name: pinba2
    restart: always
    ports:
      - "3002:3002/udp"
      - "3306:3306/tcp"
    build:
      context: .
      dockerfile: Dockerfile

[anton-povarov]

Just stumbled on this issue by accident, sorry!
Please try latest master (updated today), there was a bug with approx row count calculation (although it should've resulted in SIGFPU, not SIGSEGV) recently introduced on master (but not existing in 2.3.1).

[anton-povarov]

Tried your tables quickly, but was unable to reproduce (though i'm not using the container, just local build) - will try again tomorrow.

[anton-povarov]

Also, please try in mysql

set global pinba_log_level=debug;
set global pinba_packet_debug=1;
set global pinba_packet_debug_fraction=1;

it should start dumping all received packed info to log

[anton-povarov]

was able to reproduce with Dockerfile built container. suspect issues with build itself.

[alexanderilyin]

@anton-povarov I'm not sure if I can help anyhow on the current stage, so I'm planning to work on automation for functional tests so we can have regression tests using one of these services:

• https://circleci.com
• https://travis-ci.org

The main problem I'm not sure what is the right way to distribute PHP extension. I'm building it right now from sources, but was thinking about packing it in for PECL or for Ubuntu/Alpine.

• https://github.com/AnchorFree/docker-php-base/blob/master/Dockerfile#L107-L109
• https://github.com/AnchorFree/docker-php-base/blob/master/Dockerfile#L115-L118

[anton-povarov]

[Switching to Thread 0x7fffdadfd700 (LWP 400)]
0x0000000000031e36 in ?? ()
(gdb)
(gdb)
(gdb) bt
#0  0x0000000000031e36 in ?? ()
#1  0x00007fffe80a53ca in dictionary_word_hasher_t::operator() (this=0x7fffdadfcbf8, key=...) at ../include/pinba/dictionary.h:99
#2  std::__detail::_Hash_code_base<meow::string_ref<char const>, std::pair<meow::string_ref<char const> const, boost::intrusive_ptr<repacker_dictionary_t::word_t> >, std::__detail::_Select1st, dictionary_word
_hasher_t, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, true>::_M_hash_code (this=0x7fffdadfcbf8, __k=...) at /usr/include/c++/6.4.1/bits/hashtable_policy.h:1255
#3  std::_Hashtable<meow::string_ref<char const>, std::pair<meow::string_ref<char const> const, boost::intrusive_ptr<repacker_dictionary_t::word_t> >, std::allocator<std::pair<meow::string_ref<char const> con
st, boost::intrusive_ptr<repacker_dictionary_t::word_t> > >, std::__detail::_Select1st, std::equal_to<meow::string_ref<char const> >, dictionary_word_hasher_t, std::__detail::_Mod_range_hashing, std::__detail
::_Default_ranged_hash, std::__detail::_Prime_rehash_policy, std::__detail::_Hashtable_traits<true, false, true> >::find (__k=..., this=0x7fffdadfcbf8) at /usr/include/c++/6.4.1/bits/hashtable.h:1292
#4  std::unordered_map<meow::string_ref<char const>, boost::intrusive_ptr<repacker_dictionary_t::word_t>, dictionary_word_hasher_t, std::equal_to<meow::string_ref<char const> >, std::allocator<std::pair<meow:
:string_ref<char const> const, boost::intrusive_ptr<repacker_dictionary_t::word_t> > > >::find (__x=..., this=0x7fffdadfcbf8) at /usr/include/c++/6.4.1/bits/unordered_map.h:851
#5  repacker_dictionary_t::get_or_add (this=this@entry=0x7fffdadfcbf0, word=...) at ../include/pinba/dictionary.h:571
#6  0x00007fffe809caa6 in pinba_request_to_packet<repacker_dictionary_t> (nmpa=<optimized out>, d=0x7fffdadfcbf0, r=<optimized out>) at ../include/pinba/packet.h:164
#7  (anonymous namespace)::aux::repacker_impl_t::<lambda(timeval_t)>::operator() (now=..., __closure=<optimized out>) at repacker.cpp:431
#8  nmsg_poller_t::poller___nn_sock_t<(anonymous namespace)::aux::repacker_impl_t::worker_thread(uint32_t, nmsg_socket_t&)::<lambda(timeval_t)> >::callback(timeval_t) (this=<optimized out>, now=...)
    at ../include/pinba/nmsg_poller.h:109
#9  0x00007fffe80a00af in nmsg_poller_t::poll_and_callback (wait_for_ms=<optimized out>, pfd_size=2, pfd=0x7fffdadfc9b0, this=0x7fffdadfcb80) at ../include/pinba/nmsg_poller.h:386
#10 nmsg_poller_t::loop (this=this@entry=0x7fffdadfcb80) at ../include/pinba/nmsg_poller.h:347
#11 0x00007fffe809bf1c in (anonymous namespace)::aux::repacker_impl_t::worker_thread (this=0x7ffff3675000, thread_id=0, input_sock=...) at repacker.cpp:469

the top frame is completely broken, although the jump to the hash function seems legit and registers seem to be fine. And calling the function from debugger seems fine as well.

currently i suspect that the cause is that we're building with src rpm, but injecting the pinba module to pre-build fedora rpm. Will try and investigate more today.

The quicker fix for you might be to build mysql/mariadb from official downloaded source (that's what we do internally at Badoo anyway).

[anton-povarov]

@alexanderilyin please try this branch, fixes the issue for me.

[alexanderilyin]

@anton-povarov only today I had time to check it one more time, and it worked on dev environment. There is only one unexpected thing so far:

Standard input code as a script_name in report_by_script_name table, for example:

root@example:~# docker exec -ti pinba2 mysql -e "SELECT * FROM pinba.report_by_script_name;"
+-----------------------------------------------------------+-----------+-------------+----------------+------------------+----------------+------------------+----------------+------------------+---------------+-----------------+------------------+-------------+
| script_name                                               | req_count | req_per_sec | req_time_total | req_time_per_sec | ru_utime_total | ru_utime_per_sec | ru_stime_total | ru_stime_per_sec | traffic_total | traffic_per_sec | memory_footprint | p50         |
+-----------------------------------------------------------+-----------+-------------+----------------+------------------+----------------+------------------+----------------+------------------+---------------+-----------------+------------------+-------------+
| Standard input code                                       |         2 |   0.0333333 |             25 |         0.000584 |  0.00000973333 |       0.00742734 |        0.00003 |        0.0000005 |             0 |        0.000551 |                0 |  0.00785353 |
| EXPECTED_SCRIPT_NAME_HERE                                 |         3 |        0.05 |           37.5 |           2.3909 |      0.0398484 |          30.4076 |        0.11509 |       0.00191817 |            23 |         2.19068 |                0 |     31.2242 |
| EXPECTED_SCRIPT_NAME_HERE                                 |         2 |   0.0333333 |             25 |         0.005228 |   0.0000871333 |        0.0664899 |       0.005117 |     0.0000852833 |             1 |        0.000016 |                0 | 0.000228052 |
| EXPECTED_SCRIPT_NAME_HERE                                 |         1 |   0.0166667 |           12.5 |          5.46613 |      0.0911021 |          69.5185 |       0.371677 |       0.00619462 |            76 |         4.82471 |                0 |     68.7677 |
+-----------------------------------------------------------+-----------+-------------+----------------+------------------+----------------+------------------+----------------+------------------+---------------+-----------------+------------------+-------------+

root@example:~# docker exec -ti pinba2 mysql -e "SELECT * FROM pinba.report_by_script_name;"
+----------------------------------------+-----------+-------------+----------------+------------------+----------------+------------------+----------------+------------------+---------------+-----------------+------------------+--------+
| script_name                            | req_count | req_per_sec | req_time_total | req_time_per_sec | ru_utime_total | ru_utime_per_sec | ru_stime_total | ru_stime_per_sec | traffic_total | traffic_per_sec | memory_footprint | p50    |
+----------------------------------------+-----------+-------------+----------------+------------------+----------------+------------------+----------------+------------------+---------------+-----------------+------------------+--------+
| EXPECTED_SCRIPT_NAME_HERE              |         1 |   0.0166667 |             20 |         0.648672 |      0.0108112 |          99.1223 |       0.024154 |      0.000402567 |            82 |        0.379035 |                0 | 99.853 |
| Standard input code                    |         2 |   0.0333333 |             40 |         0.000595 |  0.00000991667 |        0.0909208 |       0.000033 |       0.00000055 |             0 |        0.000558 |                0 |  0.147 |
| EXPECTED_SCRIPT_NAME_HERE              |         2 |   0.0333333 |             40 |         0.005149 |   0.0000858167 |         0.786808 |       0.005142 |        0.0000857 |            18 |               0 |                0 |      0 |
+----------------------------------------+-----------+-------------+----------------+------------------+----------------+------------------+----------------+------------------+---------------+-----------------+------------------+--------+

P. S.

Test data was delivered successfully from both CLI and FPM SAPI using old pinba extension, but I'm not sure what is causing Standard input code. It might be an issue n our side in pinba extension configuration for PHP.

[alexanderilyin]

@anton-povarov I need some help with porting MySQL configuration options from Pinba1 to Pinab2:

• pinba_stats_history was replaced with pinba_default_history_time_sec.
• pinba_stats_gathering_period was removed.
• pinba_temp_pool_size was removed.
• pinba_request_pool_size was removed.

Could you please confirm that my assumptions are correct?

[anton-povarov]

Regarding "Standard Input Code" - no idea what that is, pinba definitely never sets anything like this by itself. Might be a bug, but there are no strings like this anywhere in source code.
Please check client code, and if you got a reproduce or more info - that'd be helpful.

Regarding settings: your assumptions are correct.

• pinba_stats_history was removed, as history time is configured per report now, and pinba_default_history_time_sec is the default value.
• other settings are not needed in pinba2, due to internal rework.

[anton-povarov]

is this Standard input code present in other reports that have script_name field?
if you enable debug (as described in one of the above comments) - does it show as arriving with packets over the network ?

[afletchgit]

More info about 'Standard input code' in the script_name

Pinba extension sends this script_name to a server after run a script /usr/lib/php/sessionclean on Linux systems. The script runs by a cron (at least on systems like Debian)