GET 24/7 LIVE HELP NOW

Announcement

Announcement Module
Collapse
No announcement yet.

What is Profile_query_end?

Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • What is Profile_query_end?

    Hi!
    Insert into InnoDB table are too slow. Below is an excerpt from slow_log:

    # Query_time: 0.635458 Lock_time: 0.000028 Rows_sent: 0 Rows_examined: 0 Rows_affected: 1 Rows_read: 0# Bytes_sent: 19 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0# Profile_starting: 0.000018 Profile_starting_cpu: 0.000018 Profile_checking_permissions: 0.000003 Profile_checking_permissions_cpu: 0.000002 Profile_Opening_tables: 0.000006 Profile_Opening_tables_cpu: 0.000006 Profile_System_lock: 0.000002 Profile_System_lock_cpu: 0.000002 Profile_init: 0.000006 Profile_init_cpu: 0.000006 Profile_update: 0.000025 Profile_update_cpu: 0.000025 Profile_Waiting_for_query_cache_lock: 0.000001 Profile_Waiting_for_query_cache_lock_cpu: 0.000001 Profile_update: 0.000004 Profile_update_cpu: 0.000004 Profile_end: 0.000001 Profile_end_cpu: 0.000001 Profile_query_end: 0.635375 Profile_query_end_cpu: 0.000263 Profile_closing_tables: 0.000007 Profile_closing_tables_cpu: 0.000007 Profile_freeing_items: 0.000012 Profile_freeing_items_cpu: 0.000011 Profile_logging_slow_query: 0.000001 Profile_logging_slow_query_cpu: 0.000001# Profile_total: 0.635460 Profile_total_cpu: 0.000347# InnoDB_trx_id: C3FEF74# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No# Filesort: No Filesort_on_disk: No Merge_passes: 0# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000# InnoDB_pages_distinct: 4INSERT INTO `logs` (userid, date, ip, ip1, host, domain, address, referer, browser) VALUES ('32f1d43dcc84ff1d5a2f1da2d7b1e35d', 1321853873, INET_ATON('1.2.3.4'), '', '', 'www.company.com', '/lib/action.php', 'http://www.company.com/cart', 'Mozilla/5.0 (Windows NT 5.1; rv:6.0) Gecko/20100101 Firefox/6.0');

    Table structure is as follows:

    CREATE TABLE logs( id INT(11) NOT NULL AUTO_INCREMENT, userid CHAR(32) NOT NULL, `date` INT(11) NOT NULL, ip BIGINT(20) NOT NULL DEFAULT 0, ip1 CHAR(255) NOT NULL, host CHAR(255) NOT NULL, domain CHAR(50) NOT NULL, address VARCHAR(1023) NOT NULL, referer VARCHAR(1023) NOT NULL, browser VARCHAR(511) NOT NULL, PRIMARY KEY (id), INDEX `date` (`date`))ENGINE = INNODBAVG_ROW_LENGTH = 904CHARACTER SET utf8COLLATE utf8_unicode_ci

    Maybe, long VARCHARs do matter?

  • #2
    By the way,
    CPU: 2x X5687 3.6 GHz
    RAM: 96 GB
    HDD: RAID10 with BBWC
    OS: CentOS 6
    Percona Server 5.5.16
    my.cnf:

    skip-external-lockingskip-name-resolveft_min_word_len = 4back_log = 100max_connections = 200max_user_connections = 200interactive_timeout = 120wait_timeout = 120connect_timeout = 5key_buffer_size = 6Gmyisam_sort_buffer_size = 4095Mjoin_buffer_size = 1Msort_buffer_size = 2Mtable_cache = 2048thread_cache_size = 286thread_stack = 196Kmax_allowed_packet = 16Mmax_connect_errors = 10max_heap_table_size = 1Gtmp_table_size = 64Minnodb_data_file_path = ibdata1:10M:autoextendinnodb_file_per_tableinnodb_ buffer_pool_size = 40Ginnodb_additional_mem_pool_size = 20Minnodb_log_file_size = 1900Minnodb_log_buffer_size = 16Minnodb_flush_log_at_trx_commit = 1innodb_flush_method = O_DIRECTinnodb_lock_wait_timeout = 50innodb_thread_concurrency = 32transaction_isolation = REPEATABLE-READ# Profiling queriesslow-query-log = 0long_query_time = 0.5log_slow_rate_limit = 1log_slow_verbosity = full,profilingquery_response_time_stats = ON# Replicationserver-id = 103binlog-format = MIXEDlog-bin = mysql-binlog-bin-index = mysql-bin.indexrelay-log = relay-logrelay-log-index = relay-log.indexexpire_logs_days = 10log-slave-updates = 1sync_binlog = 1binlog_cache_size = 1M

    Comment


    • #3
      Can you reproduce this by inserting into the table yourself, and using SHOW PROFILES? Or is this query only slow sometimes?

      Comment


      • #4
        +------------------------------+----------+| Status | Duration |+------------------------------+----------+| starting | 0.000037 || checking permissions | 0.000004 || Opening tables | 0.000009 || System lock | 0.000003 || init | 0.000009 || update | 0.000058 || Waiting for query cache lock | 0.000002 || update | 0.000016 || end | 0.000002 || query end | 0.003003 || closing tables | 0.000007 || freeing items | 0.000017 || logging slow query | 0.000001 || cleaning up | 0.000001 |+------------------------------+----------+

        Yes, it is sometimes slow, maybe 1/50 or 1/100.

        Comment


        • #5
          That sounds like there are two possibilities:

          1. Caching -- sometimes the query is satisfied from some cache, and sometimes it has to execute or hit disk instead of RAM.

          2. Interaction with other queries on the system. My money is on this option. I'd enable the slow query log with long_query_time=0 and look just for queries that finished just prior to this one when it's slow. Queries are logged at statement end, so if something's interfering, it will typically finish, go into the log, and the query you're seeing will be free to go ahead and complete and be logged afterwards.

          Comment

          Working...
          X