search

epermana / tungsten-replicator

Automatically exported from code.google.com/p/tungsten-replicator
1 stars 0 forks source link

Query on information_schema causing MySQL dying #451

Open GoogleCodeExporter opened 9 years ago

GoogleCodeExporter commented 9 years ago 
Sorry I don't follow the issue template.

Just want to know why replicator issues the following weird sql on our slave 
server and what's that for, the query takes ages to complete and if I run 
explain on that query, MySQL says it will scan all databases.

I am using fall-in topology, three master servers(two MySQL 5.5, one MySQL 
5.1), one slave (MySQL 5.6).

Here is the SQL:

SELECT NULL AS table_cat, table_schema AS table_schem, table_name, column_name,
CASE data_type
WHEN 'int'
THEN 4
WHEN 'mediumint'
THEN 4
WHEN 'varchar'
THEN 12
WHEN 'datetime'
THEN 93
WHEN 'date'
THEN 91
WHEN 'time'
THEN 92
WHEN 'text'
THEN 12
WHEN 'bigint'
THEN -5
WHEN 'varbinary'
THEN -3
WHEN 'timestamp'
THEN 93
WHEN 'double'
THEN 8
WHEN 'bit'
THEN -7
END data_type, column_type type_name, character_maximum_length column_size, 0 
buffer_length, numeric_precision decimal_digits, numeric_scale num_prec_radix, 
if( is_nullable = 'yes', 1, 0 ) nullable, column_comment remarks, 
column_default column_def, 0 sql_data, 0 sql_datetime_sub, 
character_octet_length char_octet_length, ordinal_position, is_nullable, NULL 
scope_catalog, NULL scope_schema, NULL scope_table, NULL source_data_type, 
''is_autoincrement
FROM information_schema.columns
WHERE table_schema LIKE 'livecrm'
AND table_name LIKE 'logs'
AND column_name LIKE '%'
ORDER BY table_cat, table_schem, table_name, ordinal_position

Original issue reported on code.google.com by stanley....@ityin.net on 11 Feb 2013 at 11:01

GoogleCodeExporter commented 9 years ago 
Why do you think this is a query from Replicator? It doesn't look like it's 
coming from Replicator. Is there a corresponding entry in THL? If so, please 
attach `./thl list -seqno X` output of this query.

Original comment by linas.vi...@continuent.com on 12 Feb 2013 at 12:22

GoogleCodeExporter commented 9 years ago 
We are using a unique username for replicator, and from the output of mysql 
processlist it's the user who was running it.

After some investigation, I think replicator was probably doing some data 
verification before it executes the row-based binlog SQL. By the way, we are 
using mixed binlog format on all our servers.

Here is the output form thl list:

2013-02-12 20:48:32,545 [ - main] INFO  thl.log.DiskLog Using directory 
'/opt/tungsten/fanin/thl/bravo/' for replicator logs                            

2013-02-12 20:48:32,549 [ - main] INFO  thl.log.DiskLog Checksums enabled for 
log records: true                                                               

2013-02-12 20:48:32,565 [ - main] INFO  thl.log.DiskLog Using read-only log 
connection                                                                      

2013-02-12 20:48:32,577 [ - main] INFO  thl.log.DiskLog Loaded event serializer 
class: com.continuent.tungsten.replicator.thl.serializer.ProtobufSerializer     

2013-02-12 20:48:32,592 [ - main] INFO  thl.log.LogIndex Building file index on 
log directory: /opt/tungsten/fanin/thl/bravo
2013-02-12 20:48:32,709 [ - main] INFO  thl.log.LogIndex Constructed index; 
total log files added=3
2013-02-12 20:48:32,710 [ - main] INFO  thl.log.DiskLog Validating last log 
file: /opt/tungsten/fanin/thl/bravo/thl.data.0000000003
2013-02-12 20:48:33,714 [ - main] INFO  thl.log.DiskLog Setting up log flush 
policy: fsyncIntervalMillis=0 fsyncOnFlush=false
2013-02-12 20:48:33,761 [ - main] INFO  thl.log.DiskLog Idle log connection 
timeout: 28800000ms
2013-02-12 20:48:33,761 [ - main] INFO  thl.log.DiskLog Log preparation is 
complete
SEQ# = 72420 / FRAG# = 0 (last frag)
- TIME = 2013-02-12 02:05:08.0
- EPOCH# = 0
- EVENTID = mysql-bin.000003:0000000203747614;0
- SOURCEID = SOME_SERVER
- METADATA = [mysql_server_id=2;service=bravo;shard=livecrm]
- TYPE = com.continuent.tungsten.replicator.event.ReplDBMSEvent
- SQL(0) =
 - ACTION = UPDATE
 - SCHEMA = livecrm
 - TABLE = logs
 - ROW# = 0
  - COL(1: ) = 70665
  - COL(2: ) = 2013-02-11 23:30:31.0
  - COL(3: ) = [B@605036e8
  - COL(4: ) = [B@3244eabe
  - COL(5: ) = 2013-02-12 02:05:08.0
  - COL(6: ) = [B@4a8f79ba
  - KEY(1: ) = 70665
  - KEY(2: ) = 2013-02-11 23:30:31.0
  - KEY(3: ) = [B@1180c894
  - KEY(4: ) = [B@1df07586
  - KEY(5: ) = 2013-02-12 01:59:57.0
  - KEY(6: ) = [B@15b3bfc5

Original comment by stanley....@ityin.net on 12 Feb 2013 at 8:44

GoogleCodeExporter commented 9 years ago 
Might be (a) JDBC driver asking metadata from MySQL or (b) MySQL itself for 
performance statistics or (c) a bug in MySQL 5.6. Have you tried this on 5.5?

Please provide:

* Exact MySQL 5.6 version,
* static-bravo.properties file (remove passwords if they are sensitive),
* tungsten-installer call used to set this slave up,
* EXPLAIN output.

P.S. I renamed this issue a bit.

Original comment by linas.vi...@continuent.com on 13 Feb 2013 at 6:07

GoogleCodeExporter commented 9 years ago 
No, I didn't try on 5.5. It was running on 5.1, but I didn't notice the SQL 
because we don't have any products using the DB at that time.

* I am using MySQL 5.6.10 on RedHat Enterprise Linux 6.3 (64bit) for the fan-in 
slave, and using MySQL 5.1.16 on CentOS 6.3(64bit) for bravo master.

* Please find the attached static-bravo.properties

* Here is the tungsten-installer calles:
./tools/tungsten-installer -a --master-slave --master-host=<MASTER_SERVER> 
--datasource-port=3306 --datasource-user=<USERNAME> 
--datasource-password=<PASSWORD> --datasource-log-directory=/var/lib/mysql 
--service-name=bravo --net-ssh-option=port=<PORT> 
--svc-extractor-filters=replicate 
--property=replicator.filter.replicate.ignore=test.*,mysql.*,information_schema.
*,performance_schema.* --property=replicator.auto_enable=false 
--home-directory=/opt/tungsten/fanin --cluster-hosts=<MASTER_SERVER>

/opt/tungsten/fanin/tungsten/tools/configure-service --host=<SLAVE_SERVER> 
--advanced -C -q --local-service-name=echo --role=slave --service-type=remote 
--log-slave-updates=true --datasource=<DATA_SOURCE> 
--property=replicator.auto_enable=false --master-thl-host=<MASTER_SERVER> 
--svc-start bravo

* Which output do you want me to explain?

Original comment by stanley....@ityin.net on 13 Feb 2013 at 9:01

Attachments:

GoogleCodeExporter commented 9 years ago 
in case you need it, the following is snippet from mysqlbinlog command line. 
What I don't understand is that the SQL from thl is actually right above the 
position stated in thl list log: mysql-bin.000003:0000000203747614

# at 203747249
# at 203747306
#130212  2:05:08 server id 2  end_log_pos 203747306     Table_map: 
`livecrm`.`logs` mapped to number 177934
#130212  2:05:08 server id 2  end_log_pos 203747534     Update_rows: table id 
177934 flags: STMT_END_F

BINLOG '
VKMZURMCAAAAOQAAAOrvJAwAAA63AgAAAAEAB2xpdmVjcm0ABGxvZ3MABggMDw8MDwYUADcANwAA
VKMZURgCAAAA5AAAAM7wJAwAAA63AgAAAAEABv//wAkUAQAAAAAAB/0W7k4SAAAOMTI0LjE2OS4x
NTYuNDMfYW5kcmV3QGZvcm1hbHdlYXJleHByZXNzLmNvbS5hdVXvIu5OEgAAGmYzNzVvazNsYmE2
OTZlNDE1OTloZDk5N2k2wAkUAQAAAAAAB/0W7k4SAAAOMTI0LjE2OS4xNTYuNDMfYW5kcmV3QGZv
cm1hbHdlYXJleHByZXNzLmNvbS5hdRwBI+5OEgAAGmYzNzVvazNsYmE2OTZlNDE1OTloZDk5N2k2
'/*!*/;
### UPDATE livecrm.logs
### WHERE
###   @1=70665 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=2013-02-11 23:30:31 /* DATETIME meta=0 nullable=0 is_null=0 */
###   @3='124.169.156.43' /* VARSTRING(20) meta=20 nullable=0 is_null=0 */
###   @4='andrew@formalwearexpress.com.au' /* VARSTRING(55) meta=55 nullable=0 
is_null=0 */
###   @5=2013-02-12 01:59:57 /* DATETIME meta=0 nullable=0 is_null=0 */
###   @6='f375ok3lba696e41599hd997i6' /* VARSTRING(55) meta=55 nullable=0 
is_null=0 */
### SET
###   @1=70665 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=2013-02-11 23:30:31 /* DATETIME meta=0 nullable=0 is_null=0 */
###   @3='124.169.156.43' /* VARSTRING(20) meta=20 nullable=0 is_null=0 */
###   @4='andrew@formalwearexpress.com.au' /* VARSTRING(55) meta=55 nullable=0 
is_null=0 */
###   @5=2013-02-12 02:05:08 /* DATETIME meta=0 nullable=0 is_null=0 */
###   @6='f375ok3lba696e41599hd997i6' /* VARSTRING(55) meta=55 nullable=0 
is_null=0 */
# at 203747534
#130212  2:05:08 server id 2  end_log_pos 203747614     Query   
thread_id=663008        exec_time=0     error_code=0

Original comment by stanley....@ityin.net on 14 Feb 2013 at 2:23

GoogleCodeExporter commented 9 years ago 
This query is generated by the JDBC driver. We will investigate if it is 
possible to get information with a less heavy query

Original comment by g.maxia on 14 Feb 2013 at 10:04

GoogleCodeExporter commented 9 years ago 
We'll use 2.1.0 instead of 2.0.8, hence moving the issues.

Original comment by linas.vi...@continuent.com on 27 Mar 2013 at 3:14

GoogleCodeExporter commented 9 years ago

Original comment by linas.vi...@continuent.com on 14 Jun 2013 at 6:56

GoogleCodeExporter commented 9 years ago

Original comment by g.maxia on 18 Jun 2013 at 8:45

GoogleCodeExporter commented 9 years ago 
Moving to 2.1.2

Original comment by linas.vi...@continuent.com on 21 Aug 2013 at 12:59

GoogleCodeExporter commented 9 years ago

Original comment by linas.vi...@continuent.com on 26 Aug 2013 at 1:54

GoogleCodeExporter commented 9 years ago 
There won't be a 2.1.3.

Original comment by linas.vi...@continuent.com on 17 Sep 2013 at 10:13

GoogleCodeExporter commented 9 years ago

Original comment by linas.vi...@continuent.com on 23 Dec 2013 at 9:51

GoogleCodeExporter commented 9 years ago 
postponing

Original comment by stephane...@continuent.com on 30 Jan 2014 at 9:21

GoogleCodeExporter commented 9 years ago

Original comment by stephane...@continuent.com on 30 Jan 2014 at 9:22

GoogleCodeExporter commented 9 years ago

Original comment by linas.vi...@continuent.com on 10 Sep 2014 at 12:51

GoogleCodeExporter commented 9 years ago

Original comment by linas.vi...@continuent.com on 19 Dec 2014 at 7:03

GoogleCodeExporter commented 9 years ago

Original comment by linas.vi...@continuent.com on 19 Jan 2015 at 2:18