Discussions
Categories
- 382.3K All Categories
- 2.1K Data
- 209 Big Data Appliance
- 1.9K Data Science
- 447.9K Databases
- 220.9K General Database Discussions
- 3.7K Java and JavaScript in the Database
- 25 Multilingual Engine
- 520 MySQL Community Space
- 465 NoSQL Database
- 7.8K Oracle Database Express Edition (XE)
- 2.9K ORDS, SODA & JSON in the Database
- 492 SQLcl
- 3.9K SQL Developer Data Modeler
- 186.2K SQL & PL/SQL
- 21K SQL Developer
- 293.3K Development
- 7 Developer Projects
- 128 Programming Languages
- 290K Development Tools
- 95 DevOps
- 3K QA/Testing
- 645.5K Java
- 24 Java Learning Subscription
- 36.9K Database Connectivity
- 149 Java Community Process
- 104 Java 25
- 22.1K Java APIs
- 137.9K Java Development Tools
- 165.3K Java EE (Java Enterprise Edition)
- 16 Java Essentials
- 144 Java 8 Questions
- 85.9K Java Programming
- 79 Java Puzzle Ball
- 65.1K New To Java
- 1.7K Training / Learning / Certification
- 13.8K Java HotSpot Virtual Machine
- 94.2K Java SE
- 13.8K Java Security
- 198 Java User Groups
- 24 JavaScript - Nashorn
- Programs
- 265 LiveLabs
- 36 Workshops
- 10.2K Software
- 6.7K Berkeley DB Family
- 3.5K JHeadstart
- 5.8K Other Languages
- 2.3K Chinese
- 166 Deutsche Oracle Community
- 1.2K Español
- 1.9K Japanese
- 229 Portuguese
Query very slow when querying by a specific value in a specific column
So here I have this very simple table, designed not in the best way imo but that's a different topic.
SQL> describe batch_log
Name Null? Type
----------------- -------- ------------
REQUEST_ID NOT NULL NUMBER(7)
LINE_NO NOT NULL NUMBER
TEXT VARCHAR2(4000)
LOG_DATE DATE
This table has an INDEX based on REQUEST_ID and LINE_NO columns.
When I run Q1 result comes back in a whim. When I run the query based on another REQUEST_ID the query takes 5+ minutes.
Q1: SELECT REQUEST_ID as "REQUEST_ID" , LINE_NO as "LINE_NO" , TEXT as "TEXT" , LOG_DATE as "LOG_DATE" FROM BATCH_LOG WHERE REQUEST_ID=5061 ORDER BY line_no;
Q2: SELECT REQUEST_ID as "REQUEST_ID" , LINE_NO as "LINE_NO" , TEXT as "TEXT" , LOG_DATE as "LOG_DATE" FROM BATCH_LOG WHERE REQUEST_ID=5060 ORDER BY line_no;
Execution plan looks exactly the same for both in num or rows and CPU cost. I ran the query with autotrace and also ran gather_stats on that particular table but still I don't understand why when I have REQUEST_ID=5060 there's millions of physical reads on the disk.
Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("REQUEST_ID"=5060)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
2465841 consistent gets
2465833 physical reads
0 redo size
980 bytes sent via SQL*Net to client
516 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
2 rows processed
Could it be the DB_CACHE size is undersized (400M)? I mean, I do think that SGA (2G) and PGA (2G) are tremendously undersized but I'm new to the company and I'm trying to push changes as quickly (and "politely") as I can.
Thoughts on DB_CACHE being undersized causing this problem?
Best Answer
-
When you say you see a 250k empty block from the stats above, which value are you referring to, free buffer inspected? Thanks for your help.
You've shown a plan which is an index range scan - so that's a starting point. There were no predicates other than the one driving the range scan, so you weren't doing a big range scan then discarding a huge amount of data after visiting the table. But you were only returning 2 rows.
Then there were four consecutive stats
physical reads 2465847 physical reads cache 2465847 physical read IO requests 2465847 physical read bytes 5050054656
You've read 2,465,847 (without the commas I was out by a factor of 10) blocks into the cache using the same number of I/O requests: so you're doing lots of single block reads. (The 5,050,054,656 bytes was how I derived 2KB blocks).
You don't have any statistics about "undo records applied", so these are not huge numbers of blocks being read from the undo tablespace; i.e. there's no read-consistency work, no delayed block cleanout, no commit-time checking going on.
For an extra confirming detail, there were no "table scan (long tables)" in the stats.
Regards
Jonathan Lewis
Answers
-
What is size of the table?
REQUEST_ID is unique index? if yes why then order by clause ?
-
REQUEST_ID is unique index? if yes why then order by clause ?
IF request_id has a unique index, then valid question. But I see no indication that is is, in fact, a unique index.
-
And whot results do you get for:
SELECT COUNT(*),SUM(LENGTH(TEXT)) FROM BATCH_LOG WHERE REQUEST_ID=5061; SELECT COUNT(*),SUM(LENGTH(TEXT)) FROM BATCH_LOG WHERE REQUEST_ID=5060;
Also, provide execution plans for both statements.
SY.
-
@saratpvv REQUEST_ID is not an Index. Index is the combination of RQUEST_ID and LINE_NO. One REQUEST_ID can have multiple lines that's why they use the order by clause
The size of the table is: 9.6GB
SELECT COUNT(*),SUM(LENGTH(TEXT)) FROM BATCH_LOG WHERE REQUEST_ID=5061;--QUICKCOUNT(*) SUM(LENGTH(TEXT))12 476SELECT COUNT(*),SUM(LENGTH(TEXT)) FROM BATCH_LOG WHERE REQUEST_ID=5060;--SLOWCOUNT(*) SUM(LENGTH(TEXT))2 111I gathered stats for the execution plan for both queries.
*******FOR REQUEST_ID=5061 QUICK*********
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID gcq4r8vt1g6w3, child number 1
-------------------------------------
SELECT COUNT(*),SUM(LENGTH(TEXT)) FROM BATCH_LOG WHERE REQUEST_ID=5061
Plan hash value: 1987396561
-------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
-------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 7 (100)| | 1 |00:00:00.01 | 10 |
| 1 | SORT AGGREGATE | | 1 | 1 | 44 | | | 1 |00:00:00.01 | 10 |
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 2 | TABLE ACCESS BY INDEX ROWID BATCHED| BATCH_LOG | 1 | 37 | 1628 | 7 (0)| 00:00:01 | 12 |00:00:00.01 | 10 |
|* 3 | INDEX RANGE SCAN | BATCH_LOG_I1 | 1 | 37 | | 5 (0)| 00:00:01 | 12 |00:00:00.01 | 6 |
------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
2 - SEL$1 / [email protected]$1
3 - SEL$1 / [email protected]$1
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------
Outline Data
-------------
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('19.1.0')
DB_VERSION('19.1.0')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX_RS_ASC(@"SEL$1" "BATCH_LOG"@"SEL$1" ("BATCH_LOG"."REQUEST_ID" "BATCH_LOG"."LINE_NO"))
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------
BATCH_TABLE_ACCESS_BY_ROWID(@"SEL$1" "BATCH_LOG"@"SEL$1")
END_OUTLINE_DATA
*/
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("REQUEST_ID"=5061)
Column Projection Information (identified by operation id):
-----------------------------------------------------------
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------
*******FOR REQUEST_ID=5060 SLOW*********
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID aux5hgc1582ut, child number 1
-------------------------------------
SELECT COUNT(*),SUM(LENGTH(TEXT)) FROM BATCH_LOG WHERE REQUEST_ID=5060
Plan hash value: 1987396561
-------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads |
-------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 7 (100)| | 1 |00:25:22.60 | 2465K| 2430K|
| 1 | SORT AGGREGATE | | 1 | 1 | 44 | | | 1 |00:25:22.60 | 2465K| 2430K|
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------
| 2 | TABLE ACCESS BY INDEX ROWID BATCHED| BATCH_LOG | 1 | 37 | 1628 | 7 (0)| 00:00:01 | 2 |00:25:22.60 | 2465K| 2430K|
|* 3 | INDEX RANGE SCAN | BATCH_LOG_I1 | 1 | 37 | | 5 (0)| 00:00:01 | 2 |00:25:22.60 | 2465K| 2430K|
-------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
2 - SEL$1 / [email protected]$1
3 - SEL$1 / [email protected]$1
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Outline Data
-------------
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('19.1.0')
DB_VERSION('19.1.0')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX_RS_ASC(@"SEL$1" "BATCH_LOG"@"SEL$1" ("BATCH_LOG"."REQUEST_ID" "BATCH_LOG"."LINE_NO"))
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
BATCH_TABLE_ACCESS_BY_ROWID(@"SEL$1" "BATCH_LOG"@"SEL$1")
END_OUTLINE_DATA
*/
Predicate Information (identified by operation id):
---------------------------------------------------
3 - access("REQUEST_ID"=5060)
Column Projection Information (identified by operation id):
-----------------------------------------------------------
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1 - (#keys=0) COUNT(*)[22], SUM(LENGTH("TEXT"))[22]
2 - "TEXT"[VARCHAR2,4000]
3 - "BATCH_LOG".ROWID[ROWID,10]
49 rows selected.
I could see the disk reads going up and staying high while running the second query. This time took about 20 mins. Oracle its not working hard at all at the CPU.
Thanks Astro
-
I can think of two reasons why you might see an oddity like this; but let's find out what those disc reads are before we go any further.
Connect with a new session.
Run the slow query, then
select name, value from v$statname sn, v$mystat ms where ms.value != 0 and sn.statistic# = ms.statistic# ;
Post the results - it will give us some idea of what is happening.
If you want to check https://jonathanlewis.wordpress.com/my-stats/ there are two more queries (if you're allowed to access the views) that will tell us a little more - but this one is likely to be the most informative.
Regards
Jonathan Lewis
To post text in fixed format: click the paragraph symbol (backwards P) to the left of the edit box, select the "quote marks" option from the pop-up, then the "code block" option from the resulting drop-down. If you highlight multiple paragraphs before doing this they will be grouped into a single code block.
-
select name, value from v$statname sn, v$mystat ms where ms.value != 0 and sn.statistic# = ms.statistic#;
Hey @Jonathan Lewis the machine gets restarted every Saturday night so I reran the 2 queries manually again. 1 took no time the other 27mins 30sec.
SQL> select 2 name, value 3 from 4 v$statname sn, 5 v$mystat ms 6 where ms.value != 0 7 and sn.statistic# = ms.statistic#; NAME VALUE ---------------------------------------------------------------- ---------- Requests to/from client 12 logons cumulative 1 logons current 1 opened cursors cumulative 64 opened cursors current 3 user calls 17 recursive calls 501 pinned cursors current 1 user logons cumulative 1 session logical reads 2466121 CPU used when call started 6363 NAME VALUE ---------------------------------------------------------------- ---------- CPU used by this session 6363 DB time 165180 user I/O wait time 159245 non-idle wait time 159245 non-idle wait count 2465903 session connect time 1624884082 process last non-idle time 1624885814 session uga memory 2272512 session uga memory max 2272512 messages sent 3 session pga memory 4317080 NAME VALUE ---------------------------------------------------------------- ---------- session pga memory max 4317080 enqueue requests 16 enqueue releases 15 physical read total IO requests 2465847 physical read total bytes 5050054656 cell physical IO interconnect bytes 5050054656 db block gets 6 db block gets from cache 6 db block gets from cache (fastpath) 5 consistent gets 2466115 consistent gets from cache 2466115 NAME VALUE ---------------------------------------------------------------- ---------- consistent gets pin 2465974 consistent gets pin (fastpath) 136 consistent gets examination 141 consistent gets examination (fastpath) 132 logical read bytes from cache 5050615808 physical reads 2465847 physical reads cache 2465847 physical read IO requests 2465847 physical read bytes 5050054656 db block changes 8 free buffer requested 2465848 NAME VALUE ---------------------------------------------------------------- ---------- dirty buffers inspected 880 pinned buffers inspected 58 hot buffers moved to head of LRU 92357 free buffer inspected 2465583 commit cleanouts 2 commit cleanouts successfully completed 2 switch current to new buffer 1 switch current caused by our pin 1 prefetched blocks aged out before use 72 shared hash latch upgrades - no wait 525808 calls to kcmgcs 18 NAME VALUE ---------------------------------------------------------------- ---------- calls to kcmgas 2 calls to get snapshot scn: kcmgss 68 redo entries 4 redo size 1628 redo synch time (usec) 562 redo synch time overhead (usec) 17 redo synch time overhead count ( 2ms) 1 redo synch writes 1 redo write info find 1 file io wait time 1592444328 undo change vector size 320 NAME VALUE ---------------------------------------------------------------- ---------- no work - consistent read gets 2465968 deferred (CURRENT) block cleanout applications 2 blocks cleaned out using minact 1 table scans (short tables) 1 table scan rows gotten 5 table scan disk non-IMC rows gotten 5 table scan blocks gotten 1 table fetch by rowid 84 table fetch continued row 3 cluster key scans 16 cluster key scan block gets 18 NAME VALUE ---------------------------------------------------------------- ---------- rows fetched via callback 5 index fetch by key 24 index range scans 63 HSC Heap Segment Block Changes 2 Heap Segment Array Updates 1 session cursor cache hits 30 session cursor cache count 17 cursor authentications 2 buffer is pinned count 99 buffer is not pinned count 184 workarea memory allocated 1606 NAME VALUE ---------------------------------------------------------------- ---------- workarea executions - optimal 17 parse time elapsed 5 parse count (total) 44 parse count (hard) 3 execute count 63 bytes sent via SQL*Net to client 5977 bytes received via SQL*Net from client 4033 SQL*Net roundtrips to/from client 12 sorts (memory) 33 sorts (rows) 102 98 rows selected. Elapsed: 00:00:00.21 SQL>
-
Hi @Jonathan Lewis . I logged off the sessions, logged in and ran the stats query you had on your website.
SQL> SQL> set linesize 200 SQL> select 2 name, value 3 from 4 v$statname sn, 5 v$mystat ms 6 where 7 ms.value != 0 8 and sn.statistic# = ms.statistic# 9 ; NAME VALUE ---------------------------------------------------------------- ---------- Requests to/from client 7 logons cumulative 1 logons current 1 opened cursors cumulative 6 opened cursors current 1 user calls 9 recursive calls 19 pinned cursors current 1 user logons cumulative 1 session logical reads 2466540 CPU used when call started 4498 NAME VALUE ---------------------------------------------------------------- ---------- CPU used by this session 4498 DB time 152796 user I/O wait time 147532 non-idle wait time 147532 non-idle wait count 2466136 process last non-idle time 1624889829 session uga memory 2010560 session uga memory max 2010560 messages sent 27 session pga memory 3456712 session pga memory max 3456712 NAME VALUE ---------------------------------------------------------------- ---------- enqueue requests 15 enqueue releases 14 physical read total IO requests 2466087 physical read total bytes 5050540032 cell physical IO interconnect bytes 5050540032 consistent gets 2466540 consistent gets from cache 2466540 consistent gets pin 2465821 consistent gets pin (fastpath) 9 consistent gets examination 719 consistent gets examination (fastpath) 126 NAME VALUE ---------------------------------------------------------------- ---------- logical read bytes from cache 5051473920 physical reads 2466083 physical reads cache 2466083 physical read IO requests 2466083 physical read bytes 5050537984 consistent changes 716 free buffer requested 2466089 dirty buffers inspected 10324 pinned buffers inspected 16 hot buffers moved to head of LRU 21595 free buffer inspected 2478339 NAME VALUE ---------------------------------------------------------------- ---------- CR blocks created 6 prefetched blocks aged out before use 201 shared hash latch upgrades - no wait 539273 calls to kcmgcs 13 calls to get snapshot scn: kcmgss 7 file io wait time 1475312867 transaction tables consistent reads - undo records applied 694 transaction tables consistent read rollbacks 1 data blocks consistent reads - undo records applied 18 no work - consistent read gets 2465811 rollbacks only - consistent read gets 4 NAME VALUE ---------------------------------------------------------------- ---------- cleanouts and rollbacks - consistent read gets 4 immediate (CR) block cleanout applications 4 commit txn count during cleanout 4 cleanout - number of ktugct calls 4 table scans (short tables) 1 table scan rows gotten 5 table scan disk non-IMC rows gotten 5 table scan blocks gotten 1 table fetch by rowid 2 index range scans 1 sql area evicted 1 NAME VALUE ---------------------------------------------------------------- ---------- CCursor + sql area evicted 2 session cursor cache count 4 buffer is not pinned count 6 workarea memory allocated 1633 parse time elapsed 2 parse count (total) 6 parse count (hard) 1 execute count 5 bytes sent via SQL*Net to client 3470 bytes received via SQL*Net from client 2664 SQL*Net roundtrips to/from client 7 77 rows selected. Elapsed: 00:00:00.11 SQL> SQL> select 2 event, total_waits, total_timeouts, time_waited, max_wait 3 from 4 (select /*+ no_merge */ sid from v$mystat where rownum = 1) ms, 5 v$session_event se 6 where 7 se.sid = ms.sid 8 ; EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED MAX_WAIT ---------------------------------------------------------------- ----------- -------------- ----------- ---------- Disk file operations I/O 23 0 1 0 db file sequential read 2466083 0 147531 9 SQL*Net message to client 16 0 0 0 SQL*Net message from client 15 0 56342 44492 events in waitclass Other 25 1 0 0 Elapsed: 00:00:00.00 SQL> SQL> select 2 stat_name, value 3 from 4 (select /*+ no_merge */ sid from v$mystat where rownum = 1) ms, 5 v$sess_time_model tm 6 where 7 tm.sid = ms.sid 8 and tm.value != 0 9 ; STAT_NAME VALUE ---------------------------------------------------------------- ---------- DB time 1528365931 DB CPU 45162507 parse time elapsed 2604 hard parse elapsed time 1954 sql execute elapsed time 1527939072 connection management call elapsed time 17729 PL/SQL execution elapsed time 89 7 rows selected. Elapsed: 00:00:00.01 SQL> SQL> spool off
I can see that the physical reads are too high and the file to wait time is also very high. I still don't understand why that happens only when I query for that specific REQUEST_ID. Would rebuilding the index resolve the issue? Also I've been thinking of increasing the SGA and DB_CACHE_SIZE associated with it.
Thanks
-
The figures suggest that something has left an enormous (250,000 block) hole in the middle of your index which used to hold index entries for request_id = 5060. (The reason for checking the session stats is that they might have indicated a read-consistency problem - but the absence of any "xxx - undo records applied" statistics show that this is not the case).
An oddity of this index is that it seems to be made up of blocks sized as 2KB. Is this a special tablespace, or is the entire database running with a 2KB block size?
An index rebuild (or possibly a coalesce) would address the issue - at least in the short term, but it would be good to find out why this had happened so that you could work out if there was any way to ensure that the problem didn't simply reappear in a little while.
Since there (appear to be) 250,000 empty leaf blocks in the index the most significant statistic in user_indexes/dba_indexes for the size of the index (leaf_blocks) will be completely misleading - but you can confirm that the problem is empty space by comparing the size of the index segment (user/dba_segments) with the reported leaf_blocks if the stats are up to date.
One possible explanation for the hole is that (possibly historically - you haven't supplied a version) request_id 5060 was the lowest request_id in the index and was inserting several hundred rows with increasing values for line_no each day, and then deleting them. If the next batch of inserts were for higher line_no values than the previous batch then Oracle might never get around to marking the leaf blocks with the lower values as empty.
Regards
Jonathan Lewis
-
Hey @Jonathan Lewis you're right about the size blocks, they're using (or should I say we now that I inherited this) 2k blocks since Oracle 8 I believe, have upgraded once in a while the clients DB but not the db size block, so most of the tables, other than those who contain LOBs are 2k blocks. Upgrading all of these 700+ single instance DB to 8k blocks will be another task which I'm planning right now.
As per the oddity, someone caught a bug on the application which was trying to run something without a from/to date and that created a loop on this table and caused the issue I think.
When you say you see a 250k empty block from the stats above, which value are you referring to, free buffer inspected? Thanks for your help.
-
When you say you see a 250k empty block from the stats above, which value are you referring to, free buffer inspected? Thanks for your help.
You've shown a plan which is an index range scan - so that's a starting point. There were no predicates other than the one driving the range scan, so you weren't doing a big range scan then discarding a huge amount of data after visiting the table. But you were only returning 2 rows.
Then there were four consecutive stats
physical reads 2465847 physical reads cache 2465847 physical read IO requests 2465847 physical read bytes 5050054656
You've read 2,465,847 (without the commas I was out by a factor of 10) blocks into the cache using the same number of I/O requests: so you're doing lots of single block reads. (The 5,050,054,656 bytes was how I derived 2KB blocks).
You don't have any statistics about "undo records applied", so these are not huge numbers of blocks being read from the undo tablespace; i.e. there's no read-consistency work, no delayed block cleanout, no commit-time checking going on.
For an extra confirming detail, there were no "table scan (long tables)" in the stats.
Regards
Jonathan Lewis
