dble icon indicating copy to clipboard operation
dble copied to clipboard

“flushSlowLogPeriod” in server.xml does not work for slow query log

Open yexiaoli88 opened this issue 6 years ago • 1 comments

  • dble version:version: 5.6.29-dble-9.9.9.9-4ecbd6a-20180907104021
  • preconditions :
create table test (id int,name varchar(20));
  • configs:

schema.xml

	<table name="test" dataNode="dn1,dn2,dn3,dn4" rule="sharding-by-mod" />

rule.xml

<tableRule name="sharding-by-mod">
        <rule>
            <columns>id</columns>
            <algorithm>hashmod</algorithm>
        </rule>
</tableRule>
<function name="hashmod" class="Hash">
        <property name="partitionCount">4</property>
        <property name="partitionLength">1</property>
    </function>


server.xml

 <system>
        <property name="defaultSqlParser">druidparser</property>
	<property name="useGlobleTableCheck">1</property>
	<property name="processors">1</property>
        <property name="processorExecutor">1</property>
	<property name="enableSlowLog">1</property>
	<property name="slowLogBaseDir">./slowlogs</property>
	<property name="slowLogBaseName">slow-query</property>
	<property name="sqlSlowTime">5</property>
	<property name="flushSlowLogPeriod">1000</property>
	<property name="flushSlowLogSize">5</property>
    </system>

  • steps:
    1 query in dble client port
MySQL [testdb]> insert into test values(14,'test14');
Query OK, 1 row affected (0.01 sec)

2.check slow-query.log immediately

# Time: 2018-09-10T15:45:06.448000Z
# User@Host: test[test] @  [127.0.0.1]  Id:   1
# Query_time: 0.006238  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0  Read_SQL: 0.000255  Prepare_Push: 0.001437  dn3_First_Result_Fetch: 0.001114  dn3_Last_Result_Fetch: 0.003385  Write_Client: 0.003431
SET timestamp=1536565506448;
insert into test values(14,'test14');

3 query in dble client port again

MySQL [testdb]> insert into test values(16,'test16');
Query OK, 1 row affected (0.02 sec)

4.check slow-query.log immediately

# Time: 2018-09-10T15:47:05.331000Z
# User@Host: test[test] @  [127.0.0.1]  Id:   1
# Query_time: 0.021016  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0  Read_SQL: 0.000096  Prepare_Push: 0.000975  dn1_First_Result_Fetch: 0.001041  dn1_Last_Result_Fetch: 0.018854  Write_Client: 0.018904
SET timestamp=1536565625331;
insert into test values(16,'test16');

  • expect result:
    1.slow-query log should be written every 1000s when flushSlowLogSize <5
  • real result:
    1.slow-query log has been written immediately after every slow query

yexiaoli88 avatar Sep 10 '18 08:09 yexiaoli88

Every flushSlowLogPeriod JVM tell OS to force flush disk, If OS is free in other time, it may flush to disk by itself

yanhuqing666 avatar Oct 10 '18 08:10 yanhuqing666