Home » RDBMS Server » Server Utilities » SELECT on external is very slow
SELECT on external is very slow [message #592662] |
Sat, 10 August 2013 13:53  |
scottwmackey
Messages: 515 Registered: March 2005
|
Senior Member |
|
|
Hi all,
I understand that nobody can debug this from where you are, but I was wondering if anybody has seen anything like this or if they have any insights into what could be going on. I just did a 112G file migration of production data using oracle_datapump so I know this works in principle. When I tried it on my test instance I am seeing stuff like this
[oracle@aggs00.test for_test]$ ls -l aggs_day_conversion_agg_2419
-rw-r----- 1 oracle oracle 15917056 Aug 10 09:06 aggs_day_conversion_agg_2419
CREATE TABLE IMP_3251198_2419(
PARTITION_DATE DATE,
USER_ID NUMBER,
SID NUMBER,
ACCOUNT_ID NUMBER,
EX_CAMPAIGN_ID NUMBER,
EX_ADGROUP_ID NUMBER,
EX_TERM_ID NUMBER,
EX_CREATIVE_ID NUMBER,
EF_HASH_ID NUMBER,
CONVERSION_TYPE VARCHAR2(4000),
CONVERSIONS NUMBER,
LAST_UPDATE DATE)
ORGANIZATION EXTERNAL
( TYPE ORACLE_DATAPUMP
DEFAULT DIRECTORY "FOR_TEST"
ACCESS PARAMETERS (NOLOGFILE)
LOCATION("FOR_TEST":'aggs_day_conversion_agg_2419')
);
SQL> select * from IMP_3251198_2419 where rownum < 2;
PARTITION_DATE USER_ID SID ACCOUNT_ID EX_CAMPAIGN_ID EX_ADGROUP_ID EX_TERM_ID EX_CREATIVE_ID EF_HASH_ID CONVERSION_TYPE CONVERSIONS LAST_UPDATE
-------------- ---------- ---------- ---------- -------------- ------------- ---------- -------------- ---------- -------------------------------------------------------------------------------- ----------- -----------
2012-06-01 2419 3 100000762 13413968 539952308 2293111868 13153197728 2897334409 Lead 1 2012-06-06
Executed in 1800.642 seconds
Does anybody have any idea why it could be taking 1800 seconds to select one record from a not very big table? File corruption? Disc fragmentation? Oracle instance configuration? I'll take all guesses and conjectures. Could it be something that I've done wrong?
|
|
|
|
|
|
Re: SELECT on external is very slow [message #592672 is a reply to message #592666] |
Sat, 10 August 2013 16:40   |
Lalit Kumar B
Messages: 3174 Registered: May 2013 Location: World Wide on the Web
|
Senior Member |
|
|
scottwmackey wrote on Sun, 11 August 2013 01:57I did that, but I don't see anything. import.txt is the output of tkprof. The raw trace is too big to post. The actual SELECT on the external table is at the end of import.txt. Search on ACCOUNT_ORA_GTT. (It's a different table than the one I posted, but same problem.) It just shows a huge elapsed time and nothing else. I ran the trace using ALTER SESSION SET EVENTS='10046 trace name context forever, level 12';, which I assumed would show me everything I might need. I just can't see anything interesting, which is not to say it's not there. I just don't know what to look for.
You don't have to look for anything further, before you clarify something. Looking at the tkprof output, I see the user being used is SYS.
I can see things like SELECT USER
FROM
SYS.DUAL
Also,
select decode(u.type#, 2, u.ext_username, u.name), o.name, t.update$,
t.insert$, t.delete$, t.enabled, decode(bitand(t.property, 8192),
8192, 1, 0), decode(bitand(t.property, 65536), 65536, 1, 0),
decode(bitand(t.property, 131072), 131072, 1, 0), (select o.name
from
obj$ o where o.obj# = u.spare2 and o.type# =57) from sys.obj$ o,
sys.user$ u, sys.trigger$ t, sys.obj$ bo where t.baseobject=bo.obj# and
bo.name = :1 and bo.spare3 = :2 and bo.namespace = 1 and t.obj#=o.obj#
and o.owner#=u.user# and o.type# = 12 and bitand(property,16)=0 and
bitand(property,8)=0 order by o.obj#
That explains that you are working on user SYS. If you connect as SYSDBA, your schema name will appear to be SYS. Question is why do you need to log in as sys?
SYS or SYSTEM are Oracle's internal data dictionary accounts and not for general use.
SYS/SYSDBA is special
SYS, SYSDBA, SYSOPER, SYSTEM
By any chance, is it true whatever I just posted? Or someone else could better verify again. Too late at night for me to believe my eyes!
[EDIT : Corrected typo errors]
[Updated on: Sat, 10 August 2013 16:44] Report message to a moderator
|
|
|
|
|
|
Re: SELECT on external is very slow [message #592676 is a reply to message #592675] |
Sat, 10 August 2013 17:53   |
Lalit Kumar B
Messages: 3174 Registered: May 2013 Location: World Wide on the Web
|
Senior Member |
|
|
That seems correct and obvious as FTS on the table IMP_3251037_3400 takes 1801.65 seconds.
INSERT /*+ APPEND */ INTO ACCOUNT_ORA_GTT
(PARTITION_DATE,USER_ID,ACCOUNT_ID,SID,IMPS,CLICKS,TOTAL_COST)
SELECT PARTITION_DATE,USER_ID,ACCOUNT_ID,SID,IMPS,CLICKS,TOTAL_COST
FROM IMP_3251037_3400 t
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.01 0 603 0 0
Execute 1 0.93 1801.65 0 0 3 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.94 1801.66 0 603 3 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 35 (recursive depth: 2)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 LOAD AS SELECT (cr=0 pr=0 pw=0 time=58 us)
0 0 0 EXTERNAL TABLE ACCESS FULL IMP_3251037_3400 (cr=0 pr=0 pw=0 time=1 us cost=39 size=1423320 card=16360)
|
|
|
|
|
|
|
|
Re: SELECT on external is very slow [message #592690 is a reply to message #592668] |
Sun, 11 August 2013 02:16   |
scottwmackey
Messages: 515 Registered: March 2005
|
Senior Member |
|
|
I edited the trace file heavily so that it would fit. Most of the bulk of the file was one of these every second.
[1376171969046607] kgnfs_mntrsp:8811: KGNFS_NFSPROC3_MNT FAIL 13
[1376171969047025] kgnfs_dump_hex_data:6640: 0x7fd082b10364 len 112 lt 28
0x7fd082b10364: 8000006c df2249f4 00000000 00000002 000186a5 00000003 00000001 00000001
0x7fd082b10384: 00000034 abcdefab 0000001d 61676773 30302e74 6573742e 73636c2e 6566726f
0x7fd082b103a4: 6e746965 722e636f 6d000000 00000000 00000000 00000000 00000000 00000000
0x7fd082b103c4: 00000009 2f766f6c 2f646174 61000000
[1376171969047057] kgnfs_dump_hex_data:6640: 0x7fffbc605a58 len 328 lt 82
0x7fffbc605a58: 8000001c df2249f4 00000001 00000000 00000000 00000000 00000000 0000000d
0x7fffbc605a78: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
0x7fffbc605a98: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
0x7fffbc605ab8: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
0x7fffbc605ad8: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
0x7fffbc605af8: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
0x7fffbc605b18: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
0x7fffbc605b38: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
0x7fffbc605b58: b50c1a50 3e000000 60936209 00000000 01000000 d07f0000 48ffb082 d07f0000
0x7fffbc605b78: 58ffb082 d07f0000 a05d60bc ff7f0000 f13fb182 d07f0000 205d60bc ff7f0000
0x7fffbc605b98: 50270000 00000000 The exact numbers may have differed from block to block, but this the basic structure was the same. I ran it through a few regular expression replaces:
%s/\[\d\{16,16\}\] kgnfs_mntrsp:8811: KGNFS_NFSPROC3_MNT FAIL 13/...FAIL 13/
%s/ \[\d\{16,16\}\] kgnfs_dump_hex_data:6640: 0x7fd082b10364 len 112 lt 28/ ...len 112
%s/ \[\d\{16,16\}\] kgnfs_dump_hex_data:6640: 0x7fffbc605a58 len 328 lt 82/ ...len 328
%s/^ \w\{14,14\}:\( \+\w\{8,8\}\)\{2,8\}/ 0x.../
and ended up block that looked like this ...FAIL 13
...len 112
0x...
0x...
0x...
0x...
...len 328
0x...
0x...
0x...
0x...
0x...
0x...
0x...
0x...
0x...
0x...
0x...
I then deleted every block of this type that followed the same type of block. I posted the result, which I hope would be just the relevant raw trace. If there are any expert trace file readers out there, I would love to know what you see. It looks to me that it registers my SELECT at 2013-08-10 15:32:31.332, maybe even fetches the record, then just goes back to sleep and wakes up at 2013-08-10 16:02:39.081 and gives my data. This makes no sense to me.
|
|
|
|
|
|
|
|
Re: SELECT on external is very slow [message #592724 is a reply to message #592702] |
Sun, 11 August 2013 13:02   |
scottwmackey
Messages: 515 Registered: March 2005
|
Senior Member |
|
|
I don't think your assumptions about the nature of oracle_datapump are correct. That would mean the engineers at Oracle are pretty incompetent, which I am pretty sure they are not. Second, even if you were correct, wouldn't you think it a bit odd to take 1800 seconds to read a 15M file? That would be right around 8K/s. Just for the sake of verifying my sanity, I ran a couple of tests. First, same file, same directory, different Oracle instance on a different server on a different domain (I think).
CREATE TABLE IMP_3251198_2419(
PARTITION_DATE DATE,USER_ID NUMBER,SID NUMBER,ACCOUNT_ID NUMBER,EX_CAMPAIGN_ID NUMBER,EX_ADGROUP_ID NUMBER,EX_TERM_ID NUMBER,EX_CREATIVE_ID NUMBER,EF_HASH_ID NUMBER,CONVERSION_TYPE VARCHAR2(4000),CONVERSIONS NUMBER,LAST_UPDATE DATE)
ORGANIZATION EXTERNAL
( TYPE ORACLE_DATAPUMP
DEFAULT DIRECTORY "FOR_TEST"
ACCESS PARAMETERS (NOLOGFILE)
LOCATION("FOR_TEST":'aggs_day_conversion_agg_2419')
);
SQL> SELECT * FROM IMP_3251198_2419 WHERE ROWNUM = 1;
PARTITION_DATE USER_ID SID ACCOUNT_ID EX_CAMPAIGN_ID EX_ADGROUP_ID EX_TERM_ID EX_CREATIVE_ID EF_HASH_ID CONVERSION_TYPE CONVERSIONS LAST_UPDATE
-------------- ---------- ---------- ---------- -------------- ------------- ---------- -------------- ---------- -------------------------------------------------------------------------------- ----------- -----------
2012-06-01 2419 3 762 968 308 22931 131528 409 Lead 1 2012-06-06
Executed in 0.14 seconds
SQL> SELECT COUNT(*) FROM IMP_3251198_2419;
COUNT(*)
----------
202650
Executed in 0.14 seconds
Then I copied the file to a different directory
[oracle@aggs00.test ~]$ cp /data/for_test/aggs_day_conversion_agg_2419 /home/oracle/admin/expimp/.
and tried again on the problematic test instance
CREATE TABLE IMP_3251198_2419_E(
PARTITION_DATE DATE,USER_ID NUMBER,SID NUMBER,ACCOUNT_ID NUMBER,EX_CAMPAIGN_ID NUMBER,EX_ADGROUP_ID NUMBER,EX_TERM_ID NUMBER,EX_CREATIVE_ID NUMBER,EF_HASH_ID NUMBER,CONVERSION_TYPE VARCHAR2(4000),CONVERSIONS NUMBER,LAST_UPDATE DATE)
ORGANIZATION EXTERNAL
( TYPE ORACLE_DATAPUMP
DEFAULT DIRECTORY "EXPIMP"
ACCESS PARAMETERS (NOLOGFILE)
LOCATION("EXPIMP":'aggs_day_conversion_agg_2419')
);
SQL> SET TIMING ON
SQL> SELECT * FROM IMP_3251198_2419_E WHERE ROWNUM = 1;
PARTITION_DATE USER_ID...
-------------- ----------...
2012-06-01 2419...
Executed in 0.093 seconds
It looks to be something strange between the Oracle instance and the /data directory that is mounted to it. There is still something I am not understanding though because copying the file took less than a second, so I would think it can't be a problem with the server being able to read from the disc.
|
|
|
|
|
|
|
Re: SELECT on external is very slow [message #593197 is a reply to message #592729] |
Wed, 14 August 2013 20:58   |
scottwmackey
Messages: 515 Registered: March 2005
|
Senior Member |
|
|
Sorry for the very slow response. I had other tasks that my higher ups deemed more important. I made a smaller file.
[oracle@aggs00.test for_test]$ head -10 aggs_day_keyword_agg_3085 > aggs_day_keyword_agg_3085_10
[oracle@aggs00.test for_test]$ ls -l aggs_day_keyword_agg_3085*
-rw-r----- 1 oracle oracle 2236030976 Aug 14 10:36 aggs_day_keyword_agg_3085
-rw-rw-r-- 1 oracle oracle 8339 Aug 14 14:47 aggs_day_keyword_agg_3085_10
It makes no difference. Still exactly 30 minutes.
SQL> CREATE TABLE IMP_3251274_3085_10(
2 DEVICE VARCHAR2(1),PARTITION_DATE DATE...
3 ORGANIZATION EXTERNAL
4 ( TYPE ORACLE_DATAPUMP
5 DEFAULT DIRECTORY "FOR_TEST"
6 ACCESS PARAMETERS (NOLOGFILE)
7 LOCATION("FOR_TEST":'aggs_day_keyword_agg_3085_10')
8 );
Table created
Executed in 0.015 seconds
SQL> SELECT device,
2 partition_date,
3 user_id,
4 sid,
...
28 quality_score
29 FROM imp_3251274_3085 t
30 WHERE ROWNUM = 1;
DEVICE PARTITION_DATE...
------ --------------...
2012-01-01 ...
Executed in 1800.47 seconds
SQL> CREATE TABLE IMP_3251274_3085(
2 DEVICE VARCHAR2(1),PARTITION_DATE DATE...
3 ORGANIZATION EXTERNAL
4 ( TYPE ORACLE_DATAPUMP
5 DEFAULT DIRECTORY "FOR_TEST"
6 ACCESS PARAMETERS (NOLOGFILE)
7 LOCATION("FOR_TEST":'aggs_day_keyword_agg_3085')
8 );
Table created
Executed in 0.031 seconds
SQL> SELECT device,
2 partition_date,
3 user_id,
4 sid,
...
28 quality_score
29 FROM imp_3251274_3085 t
30 WHERE ROWNUM = 1;
DEVICE PARTITION_DATE...
------ --------------...
2012-01-01 ...
Executed in 1801.297 seconds
If I didn't know better, I would say there is something that is telling Oracle just wait 30 minutes before reading the file. I can copy the entire 2G file to the server's drive, point the external table to that file and load in about 11 minutes. That just makes no sense.
|
|
|
|
|
Re: SELECT on external is very slow [message #593202 is a reply to message #593199] |
Wed, 14 August 2013 21:46   |
scottwmackey
Messages: 515 Registered: March 2005
|
Senior Member |
|
|
First things first, I realize I made a mistake in the test I just posted. I am selecting from the same table for both of them. For the record, I have run several of these tests and the results are always consistent. I reran the test with the correct _10 external table and the results are even more interesting. This is what happens when I call the real 10 line file
Connected to Oracle Database 11g Enterprise Edition Release 11.2.0.3.0
SQL> CREATE TABLE IMP_3251274_3085_10E(
2 DEVICE VARCHAR2(1),PARTITION_DATE DATE...)
3 ORGANIZATION EXTERNAL
4 ( TYPE ORACLE_DATAPUMP
5 DEFAULT DIRECTORY "EXPIMP"
6 ACCESS PARAMETERS (NOLOGFILE)
7 LOCATION("EXPIMP":'aggs_day_keyword_agg_3085_10')
8 );
Table created
Executed in 0.062 seconds
SQL> SELECT device,
2 partition_date,
3 user_id,
4 sid,
...
28 quality_score
29 FROM imp_3251274_3085_10E t
30 WHERE ROWNUM = 1;
ORA-29913: error in executing ODCIEXTTABLEOPEN callout
ORA-31640: unable to open dump file "/home/oracle/admin/expimp/aggs_day_keyword_agg_3085_10" for read
ORA-19505: failed to identify file "/home/oracle/admin/expimp/aggs_day_keyword_agg_3085_10"
ORA-27046: file size is not a multiple of logical block size
Additional information: 1
This interesting thing is that the error comes up instantly. When I try it on the "bad" directory
SQL> CREATE TABLE IMP_3251274_3085_10T(
2 DEVICE VARCHAR2(1),PARTITION_DATE DATE...)
3 ORGANIZATION EXTERNAL
4 ( TYPE ORACLE_DATAPUMP
5 DEFAULT DIRECTORY "FOR_TEST"
6 ACCESS PARAMETERS (NOLOGFILE)
7 LOCATION("FOR_TEST":'aggs_day_keyword_agg_3085_10')
8 );
Table created
SQL> SELECT device,
2 partition_date,
3 user_id,
4 sid,
...
28 quality_score
29 FROM imp_3251274_3085_10T t
30 WHERE ROWNUM = 1;
it takes 30 minutes to show the error. It's just not trying to read anything for 30 minutes.
|
|
|
|
Goto Forum:
Current Time: Sat Feb 22 20:55:15 CST 2025
|