GET 24/7 LIVE HELP NOW

Announcement

Announcement Module
Collapse
No announcement yet.

100+ queries very sporadically

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

  • 100+ queries very sporadically

    Hello,

    I am new to the forums, so I may be a little off with the proper post 'format.' Feel free to correct me, I will not take it personal.

    So, I have a session table typically has 20K rows in it and on every webpage hit (a few per second), one SELECT and one UPDATE are executed in the same connection. In addition, a 'DELETE on data more than 2 weeks old' is performed 5% of the time.

    Sometimes, I can get locked out for 100+ sec, meanwhile, the person sitting next to me can access the data immediately.

    Here is the info for the table, and the slow queries:

    1. show create table session:
    session | CREATE TABLE `session` (
    `ctr` int(10) unsigned NOT NULL auto_increment,
    `session_id` varchar(40) NOT NULL,
    `ip_address` varchar(16) NOT NULL,
    `user_agent` varchar(50) NOT NULL,
    `referrer_user_id` int(10) unsigned default NULL,
    `referrer_addr` varchar(100) default NULL,
    `last_activity` int(10) unsigned NOT NULL,
    `session_data` text NOT NULL,
    PRIMARY KEY (`ctr`),
    UNIQUE KEY `idx_session_id` (`session_id`),
    KEY `idx_selects` (`session_id`,`user_agent`,`last_activity`)
    ) ENGINE=InnoDB AUTO_INCREMENT=24402 DEFAULT CHARSET=latin1 |

    2. slow select:
    # Query_time: 85 Lock_time: 0 Rows_sent: 1 Rows_examined: 18370
    SELECT *
    FROM session
    WHERE session_id = '06a05c42d9a58515d2bac592c3bdfc8b'
    AND last_activity > 1234638681
    AND user_agent = 'Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv';

    3. slow update:
    # Query_time: 128 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
    UPDATE session SET last_activity = 1235848241, user_agent = 'Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US
    ; rv', ip_address = '69.15.182.225', referrer_addr = '', session_data = 'a:2:{s:11:\"url_history\";a:5:{i:0;s:3
    5:\"/support/view/highestSupportAmount/\";i:1;s:37:\"/support/view/highestSupportAmount/72\ ";i:2;s:37:\"/suppor
    t/view/highestSupportAmount/36\";i:3;s:40:\"/support/design/38/skulls-are-still-kool\ ";i:4;s:34:\"/support/view
    /highestSupportAmount\";}s:16:\"referrer_user_id\"; N;}' WHERE session_id = 'a73bc2035d2ca7a58844e4ec52e48c3a';

    4. slow delete:
    # Query_time: 94 Lock_time: 0 Rows_sent: 0 Rows_examined: 0
    DELETE FROM session WHERE last_activity < 1235606350;

    I am not sure if this is a locking issue, it looks like it, but I don't know how to investigate further.

  • #2
    ad2.
    explain SELECT *
    FROM session
    WHERE session_id = '06a05c42d9a58515d2bac592c3bdfc8b'
    AND last_activity > 1234638681
    AND user_agent = 'Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv';

    ad3.
    explain select * from session WHERE session_id = 'a73bc2035d2ca7a58844e4ec52e48c3a';

    ad4.
    explain select * FROM session WHERE last_activity < 1235606350;

    Copy & paste results.

    Comment


    • #3
      ad2.
      +----+-------------+-------+------+---------------+------+-- -------+------+------+-------------------------------------- ---------------+
      | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
      +----+-------------+-------+------+---------------+------+-- -------+------+------+-------------------------------------- ---------------+
      | 1 | SIMPLE | NULL | NULL | NULL | NULL | NULL | NULL | NULL | Impossible WHERE noticed after reading const tables |
      +----+-------------+-------+------+---------------+------+-- -------+------+------+-------------------------------------- ---------------+
      1 row in set (0.00 sec)


      ad3.
      +----+-------------+-------+------+---------------+------+-- -------+------+------+-------------------------------------- ---------------+
      | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
      +----+-------------+-------+------+---------------+------+-- -------+------+------+-------------------------------------- ---------------+
      | 1 | SIMPLE | NULL | NULL | NULL | NULL | NULL | NULL | NULL | Impossible WHERE noticed after reading const tables |
      +----+-------------+-------+------+---------------+------+-- -------+------+------+-------------------------------------- ---------------+
      1 row in set (0.00 sec)


      ad4.
      +----+-------------+-------------+------+---------------+--- ---+---------+------+-------+-------------+
      | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
      +----+-------------+-------------+------+---------------+--- ---+---------+------+-------+-------------+
      | 1 | SIMPLE | ca_sessions | ALL | NULL | NULL | NULL | NULL | 18269 | Using where |
      +----+-------------+-------------+------+---------------+--- ---+---------+------+-------+-------------+
      1 row in set (0.00 sec)


      thank you

      Comment


      • #4
        Repeat 2 & 3 with valid session_id.

        As for 4 You could add index to the last_activity and check query again.

        edit:
        Check also
        explain SELECT *
        FROM session
        WHERE session_id = '06a05c42d9a58515d2bac592c3bdfc8b'
        AND user_agent = 'Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv'
        AND last_activity > 1234638681
        ;
        (with valid session_id and user_agent of course)

        btw. Your user_agent is too short, 50 chars is not enough

        Comment


        • #5
          Thank you for your help.

          ad2.

          explain SELECT *
          -> FROM ca_sessions
          -> WHERE session_id = '1ba4966d04a30c4895ac89bedfd0eced'
          -> AND last_activity > 1236803500
          -> AND user_agent = 'Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.4; en';
          +----+-------------+-------------+-------+------------------ ----------+----------------+---------+-------+------+------- +
          | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
          +----+-------------+-------------+-------+------------------ ----------+----------------+---------+-------+------+------- +
          | 1 | SIMPLE | ca_sessions | const | idx_session_id,idx_selects | idx_session_id | 42 | const | 1 | |
          +----+-------------+-------------+-------+------------------ ----------+----------------+---------+-------+------+------- +
          1 row in set (0.00 sec)


          ad3.
          mysql> explain select * from ca_sessions WHERE session_id = '1ba4966d04a30c4895ac89bedfd0eced';
          +----+-------------+-------------+-------+------------------ ----------+----------------+---------+-------+------+------- +
          | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
          +----+-------------+-------------+-------+------------------ ----------+----------------+---------+-------+------+------- +
          | 1 | SIMPLE | ca_sessions | const | idx_session_id,idx_selects | idx_session_id | 42 | const | 1 | |
          +----+-------------+-------------+-------+------------------ ----------+----------------+---------+-------+------+------- +
          1 row in set (0.00 sec)

          ad4.
          mysql> explain select * FROM ca_sessions WHERE last_activity < 1235606350;
          +----+-------------+-------------+-------+------------------ -+-------------------+---------+------+------+-------------+
          | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
          +----+-------------+-------------+-------+------------------ -+-------------------+---------+------+------+-------------+
          | 1 | SIMPLE | ca_sessions | range | idx_last_activity | idx_last_activity | 4 | NULL | 1 | Using where |
          +----+-------------+-------------+-------+------------------ -+-------------------+---------+------+------+-------------+
          1 row in set (0.16 sec)

          after adding index on last_activity:
          mysql> explain SELECT *
          -> FROM ca_sessions
          -> WHERE session_id = '1ba4966d04a30c4895ac89bedfd0eced'
          -> AND last_activity > 1236803500
          -> AND user_agent = 'Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.4; en';
          +----+-------------+-------------+-------+------------------ ----------------------------+----------------+---------+---- ---+------+-------+
          | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
          +----+-------------+-------------+-------+------------------ ----------------------------+----------------+---------+---- ---+------+-------+
          | 1 | SIMPLE | ca_sessions | const | idx_session_id,idx_selects,idx_last_activity | idx_session_id | 42 | const | 1 | |
          +----+-------------+-------------+-------+------------------ ----------------------------+----------------+---------+---- ---+------+-------+
          1 row in set (0.00 sec)


          Also, how long should the user_agent be typically, and why does it matter?

          thanks.

          Comment


          • #6
            Ok, the indexes should be fine. Does this server use query cache ? Xaprb wrote something about mysql freezes: http://www.mysqlperformanceblog.com/2009/03/19/mysql-random- freezes-could-be-the-query-cache/ . It could be also hardware problem (RAID failure). Or someone is running many queries on tables without indexes.

            Comment


            • #7
              Thanks a lot for your help.

              It appears that query_cache_size is disabled, but the query_cache_type is ON, I am not sure if it matters and what it really means.

              mysql> show variables like '%query%';
              +------------------------------+---------+
              | Variable_name | Value |
              +------------------------------+---------+
              | ft_query_expansion_limit | 20 |
              | have_query_cache | YES |
              | long_query_time | 10 |
              | query_alloc_block_size | 8192 |
              | query_cache_limit | 1048576 |
              | query_cache_min_res_unit | 4096 |
              | query_cache_size | 0 |
              | query_cache_type | ON |
              | query_cache_wlock_invalidate | OFF |
              | query_prealloc_size | 8192 |
              +------------------------------+---------+
              10 rows in set (0.01 sec)

              As for your second point, would it make sense that a query takes 100+ seconds even if tables indexes are not set properly?

              Is there anything else that I should try? I am open to any suggestions.

              Here is what I tried before:
              I launched 100 concurrent connections (with httpd_load) and they all returned in under 1 sec. This is a lot more than our typical usage. So it is not a currency issues, but more of a random locking or random cache cleaning issue.

              Comment


              • #8
                kamilski81 wrote on Wed, 25 March 2009 22:22


                It appears that query_cache_size is disabled, but the query_cache_type is ON, I am not sure if it matters and what it really means.


                You could add SQL_NO_CACHE to the queries. Mysql documentation says that You can add it to select queries.

                Quote:


                As for your second point, would it make sense that a query takes 100+ seconds even if tables indexes are not set properly?


                The more data, the more time it takes.

                Are You the only user of this database ? Several months ago I had an account on VPS (virtual server). There were few users (maybe 50 accounts). One day my page started to lag, the worst time was 2 minutes to fetch and display data. I suppose that someone was running PHPBB by Przemo, KQS or something like that. In two days Handler_read_rnd climbed from 800 M to the 4T.

                Comment


                • #9
                  @januzi, Thank you very much for your persistent help, I really appreciate it. I would like to send you a Cameesa tee if you don't mind. Please check out our site, Cameesa.com, and email me your size, which design, and address [kamil[at]cameesa[dot]com]

                  As for my solution, I have added SQL_NO_CACHE to the select query for the session table, we'll see if that helps for the time being.

                  We are actually using a VPS so I'm not sure who else is on this server. However, we are the only ones using this mysql cause I have control of the process.

                  Here is an example of what happens on our server, so I am not sure that it makes sense that some other process is slowing this down.
                  [conn]
                  19000 Connect db
                  19000 Query SELECT * from session....blah blah....
                  19001 Connect db
                  19001 Query SELECT * from session....blah blah....
                  19002 Connect db
                  19002 Query SELECT * from session....blah blah....
                  19003 Connect db
                  19003 Query SELECT * from session....blah blah....
                  19001 Connection Close
                  19002 Connection Close
                  19003 Connection Close
                  19000 Connection Close

                  So it looks like one query exectues and then it freezes for a while, meanwhile others Connect and finish. Then the conection 19000 finally closes and returns the result with 100+sec.


                  What is Handler_read_rnd?

                  Thanks again.

                  Comment


                  • #10
                    You could set
                    query_cache_type = OFF;
                    This should disable cache ("should", because there could be bug in mysql and some people have had problems even with query_cache_size = 0)


                    There are several variables to look at. I think that phpmyadmin gives good hints about those variables. Just look under status tab, and search for:
                    Handler_read_rnd
                    Handler_read_rnd_next
                    Select_full_join
                    Big values and red color mean that there is something wrong with the queries (and especially with indexes).
                    There is also Created_tmp_disk_tables and Created_tmp_tables. Second one shows how many temporary tables were made inside memory. As You know memory is faster than disk, so it is better when temporary tables are inside memory. As I remember temporary tables could be created by mysql when there is "order by".



                    Is this table innodb or myisam ?

                    Comment


                    • #11
                      I have set query_cache_type to OFF in global+session. We'll see how that works out.

                      It appears that setting SQL_NO_CACHE in select queries did not help because i just recently saw transactions that took 30+ seconds to execute.

                      We use InnodDB.As for the 'status' variables, you're on to something, here are the red variables (all the ones you mentioned)

                      Handler_read_rnd 2,984 k
                      Handler_read_rnd_next 137 M
                      Select_full_join 7,542
                      Created_tmp_disk_tables 80 k
                      Created_tmp_tables 252 k (only one not red)

                      Do you recommend I analyze each query on the website?

                      In addition these variables looked fishy as well (and were highlighted red):

                      Innodb_row_lock_time_avg 3,705
                      Innodb_row_lock_time_max 52 k
                      Innodb_row_lock_waits 60

                      Advice on where I should start?
                      Thanks for the help.

                      Comment


                      • #12
                        http://www.xaprb.com/blog/2007/09/18/how-to-debug-innodb-loc k-waits/
                        Maybe this one will help.

                        Some queries need indexes, You can find them by enabling logging slow queries and queries not using indexes (both of them have to be enabled).

                        Comment


                        • #13
                          I enabled log-queries-without-indexes and we'll see what comes up. As for the article, I tried installing innotop and got a bunch of errors. I've asked my support server team to install it. Hopefully, they do soon.

                          Will keep you updated.

                          Comment


                          • #14
                            What OS and hardware did you use ?
                            I have similar problems with RAID1 on LSI Logic SAS1068 card.
                            http://forum.percona.com/index.php/t/1143/

                            I profile query and see slow on "Ending" stage.
                            Only after innodb_flush_log_at_trx_commit=0 and this slow micro-updates seems go away.

                            Comment


                            • #15
                              I am using : CentOS release 4.5, running on :

                              Linux 2.6.18-028stab060.2 #1 SMP Tue Jan 13 10:24:09 MSK 2009 i686 i686 i386 GNU/Linux

                              In addition,

                              # tail -n 25 /proc/cpuinfo
                              power management:

                              processor : 3
                              vendor_id : GenuineIntel
                              cpu family : 6
                              model : 15
                              model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz
                              stepping : 6
                              cpu MHz : 498.751
                              cache size : 4096 KB
                              physical id : 3
                              siblings : 2
                              core id : 1
                              cpu cores : 2
                              fpu : yes
                              fpu_exception : yes
                              cpuid level : 10
                              wp : yes
                              flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm
                              bogomips : 3990.03
                              clflush size : 64
                              cache_alignment : 64
                              address sizes : 36 bits physical, 48 bits virtual
                              power management:

                              and....

                              # mount
                              /dev/vzfs on / type reiserfs (rw,usrquota,grpquota)
                              sysfs on /sys type sysfs (rw)
                              /proc on /proc type proc (rw)
                              none on /dev/pts type devpts (rw)
                              none on /proc/sys/fs/binfmt_misc type binfmt_misc (rw)



                              I am not sure how to check whether I am using raid or not? advice?

                              Comment

                              Working...
                              X