MySQL Bugs: #70172: trx_create() and trx_free() are called at every memcached get request

Bug #70172	trx_create() and trx_free() are called at every memcached get request
Submitted:	28 Aug 2013 4:37	Modified:	29 Oct 2013 11:50
Reporter:	Yoshinori Matsunobu (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S5 (Performance)
Version:	5.6.13	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	innodb_memcached plugin

Description:
Whenever executing memcached get request to InnoDB-memcached plugin, trx_create() and trx_free() are called (per each request). This is very expensive and should be reused across multiple requests. MySQL clients share trx objects across multiple queries. I want this to be supported on InnoDB-memcached plugin, too.
When I did micro-benchmarks between memcached-get vs select (running memcached-get from 100 remote clients vs running "select ... where id=x" from 100 remote clients), I got around ~300,000 qps from select, but got only 100,000 qps from memcached. mysqld was CPU bound on the memcached benchmark, and almost all resources were spent for trx_create() and trx_free() (and lots of mutex contentions caused by them).

How to repeat:
1. Run mysqld with innodb-memcached support. Attach by gdb and set breakpoints at trx_create() and trx_free().

2. Connect via memcached protocol. Run some get commands to demo table like below. You'll be able to verify that trx_create() and trx_free() are called per each request.

telnet 127.0.0.1 11211
get @@aaa.AA
VALUE @@aaa.AA 8 12
HELLO, HELLO
END
get AA
VALUE AA 8 12
HELLO, HELLO
END
get AA
VALUE AA 8 12
HELLO, HELLO
END
get AA
VALUE AA 8 12
HELLO, HELLO
END

Suggested fix:
Share trx objects across multiple requests.

Here are example stack traces
(gdb) bt
#0  trx_create () at storage/innobase/trx/trx0trx.cc:99
#1  trx_allocate_for_background () at storage/innobase/trx/trx0trx.cc:168
#2  trx_allocate_for_mysql () at storage/innobase/trx/trx0trx.cc:185
#3  ib_trx_begin(._95) (ib_trx_level=IB_TRX_READ_UNCOMMITTED) at storage/innobase/api/api0api.cc:591
#4  innodb_conn_init (engine=0x7f2928024b40, cookie=<value optimized out>, conn_option=0, lock_mode=IB_LOCK_NONE, has_lock=0 '\000') at plugin/innodb_memcached/innodb_memcache/src/innodb_engine.c:887
#5  innodb_get (handle=0x7f2928024b40, cookie=0x7f290c0008c8, item=0x7f291fffde58, key=0x7f290c000b64, nkey=8, vbucket=18652) at plugin/innodb_memcached/innodb_memcache/src/innodb_engine.c:1326
#6  process_get_command (c=0x7f290c0008c8, tokens=0x7f291fffdeb0, ntokens=<value optimized out>, return_cas=0 '\000') at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:4030
#7  process_command (c=0x7f290c0008c8, command=0x0) at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:4552
#8  try_read_command (c=0x7f290c0008c8) at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:4820
#9  conn_parse_cmd (c=0x0) at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:5250
#10 event_handler (fd=<value optimized out>, which=<value optimized out>, arg=0x7f290c0008c8) at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:5654
#11 event_process_active (base=0x7f292803d5e0, flags=<value optimized out>) at libevent/event.c:392
#12 event_base_loop (base=0x7f292803d5e0, flags=<value optimized out>) at libevent/event.c:544
#13 worker_libevent (arg=0x7f2928042d78) at plugin/innodb_memcached/daemon_memcached/daemon/thread.c:304

(gdb) bt
#0  trx_free (trx=0x7f29000009e8) at storage/innobase/trx/trx0trx.cc:205
#1  trx_free_for_mysql (trx=0x7f29000009e8) at storage/innobase/trx/trx0trx.cc:338
#2  ib_trx_release (ib_trx=0x7f29000009e8) at storage/innobase/api/api0api.cc:636
#3  ib_trx_commit (ib_trx=0x7f29000009e8) at storage/innobase/api/api0api.cc:661
#4  ib_cursor_commit_trx (ib_crsr=0x7f2900001898, ib_trx=0x0) at storage/innobase/api/api0api.cc:1377
#5  innodb_reset_conn (conn_data=0x7f29000008c0, has_lock=0 '\000', commit=1 '\001', has_binlog=0 '\000') at plugin/innodb_memcached/innodb_memcache/src/innodb_api.c:1637
#6  innodb_api_cursor_reset (engine=<value optimized out>, conn_data=0x7f29000008c0, op_type=CONN_OP_READ, commit=0 '\000') at plugin/innodb_memcached/innodb_memcache/src/innodb_api.c:1720
#7  innodb_get (handle=0x7f2928024b40, cookie=0x7f290c0008c8, item=0x7f291fffde58, key=0x7f290c000b64, nkey=201354352, vbucket=<value optimized out>) at plugin/innodb_memcached/innodb_memcache/src/innodb_engine.c:1437
#8  process_get_command (c=0x7f290c0008c8, tokens=0x7f291fffdeb0, ntokens=<value optimized out>, return_cas=0 '\000') at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:4030
#9  process_command (c=0x7f290c0008c8, command=0x0) at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:4552
#10 try_read_command (c=0x7f290c0008c8) at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:4820
#11 conn_parse_cmd (c=0x7f29000009e8) at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:5250
#12 event_handler (fd=<value optimized out>, which=<value optimized out>, arg=0x7f290c0008c8) at plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:5654
#13 event_process_active (base=0x7f292803d5e0, flags=<value optimized out>) at libevent/event.c:392
#14 event_base_loop (base=0x7f292803d5e0, flags=<value optimized out>) at libevent/event.c:544
#15 worker_libevent (arg=0x7f2928042d78) at plugin/innodb_memcached/daemon_memcached/daemon/thread.c:304

Hello Yoshinori,

Thank you for the bug report.

Thanks,
Umesh

InnoDB-Memcache is configurable with regards to transaction batching to the server.

Two values daemon_memcached_r_batch_size and daemon_memcached_w_batch_size can be set to commit the transaction every N requests. By default, this is set to 1, thus all get/set operations will run in their own transaction.

Though not documented specifically, I checked the source and this batch size appears to apply to a single client connection, that is, each memcache client gets its own transaction and counter for commands run.

Documentation here:
http://dev.mysql.com/doc/refman/5.6/en/innodb-memcached-setup.html

daemon_memcached_r_batch_size, batch commit size for read operations (get). It specifies after how many memcached read operations the system automatically does a commit. By default, this is set to 1 so that every get request can access the very latest committed data in the InnoDB table, whether the data was updated through memcached or by SQL. When its value is greater than 1, the counter for read operations is incremented once for every get call. The flush_all call resets both the read and write counters.

daemon_memcached_w_batch_size, batch commit for any write operations (set, replace, append, prepend, incr, decr, and so on) By default, this is set as 1, so that no uncommitted data is lost in case of an outage, and any SQL queries on the underlying table can access the very latest data. When its value is greater than 1, the counter for write operations is incremented once for every add, set, incr, decr, and delete call. The flush_all call resets both the read and write counters.

What I want to report here is calling trx_create()/trx_free() per every transaction is not needed. Normal MySQL select statements don't do that. You can easily verify that trx_create()/trx_free() is not called per every (auto-committed) select (or even insert) statement. I think this optimization can be done in InnoDB memcached plugin with keeping using daemon_memcached_*_batch_size==1.

The last comment was written by Yoshinori. Not sure why my profile name was registered in Japanese..

Fixed as of 5.6.15, 5.7.3, and here's the changelog entry:

"trx_create" and "trx_free" would be called for every "memcached" "get"
request. 

Thank you for the bug report.

5.6$ bzr log -r 5532
------------------------------------------------------------
revno: 5532
committer: Jimmy Yang <jimmy.yang@oracle.com>
branch nick: mysql-5.6
timestamp: Fri 2013-10-18 11:25:17 +0800
message:
  Fix bug #17371537 TRX_CREATE() AND TRX_FREE() ARE CALLED AT EVERY MEMCACHED
  GET REQUES
  
  rb://3505 approved by Sunny Bains