使用strace分析exp的奇怪問題

dbhelper發表於2014-11-26
exp算是一個經典的資料匯出工具了。對於小數量的表來說,個人還是比較鍾愛exp。畢竟expdp還需要配置directory而且還在服務端。exp在資料量小的情況下速度還是很理想的。
關於exp匯出的這個問題,已經拖了很久了,自己也排查了各種方法。透過檢視wait event,檢視exp的debug日誌,都沒有得出一些很有說服力的內容,今天下定決心來細細琢磨琢磨這個問題。有了一點收穫。
之前在測試系統中碰到一個問題,匯出一個比較大的分割槽表,分割槽數很多,其中有些分割槽裡面沒有資料,但是透過exp匯出這些沒有資料的分割槽時,平均每個分割槽都需要2秒左右的時間,如果表中有資料還可以理解,但是感覺cpu就在那空轉一樣。但是檢視程式情況,耗費的cpu資源還不少。這個表剛好有好幾百個分割槽,所以等待的時間很長,就在那看一行一行的慢慢輸出0 rows exported.
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                                                                       
17540 oraccbs1  25   0  127m  67m 8912 R 99.0  0.0   0:50.91 exp                  tables=xxxx file=a.dmp buffer=9102000   
而且奇怪的是匯出的時候強制退出也沒反應,只能手工kill程式才可以。

當時因為需要做備份需要,全庫備份太大,就使用了表匯出模式,結果匯出的時候速度很慢。無奈之下使用表匯出模式,開了多個並行視窗同時匯出,這個表就是有些特殊,還是慢。
最後在反覆嘗試之後,得出了一個折中辦法,就是把引數buffer從9M降低,速度一下子就快了起來。

strace算是一個很有效率的工具,所以今天用strace先抓了兩份日誌來對比。
以下是透過exp匯出這個分割槽表時,指定buffer為9M時的日誌,其中分割槽A1_B1中沒有資料。但是從日誌裡面看還進行了不少的操作。

write(2, ". . exporting partition         "..., 54. . exporting partition                          A1_B1) = 54
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9991b9000
brk(0x122e3000)                         = 0x122e3000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9991f6000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999233000
brk(0x12305000)                         = 0x12305000
brk(0x12327000)                         = 0x12327000
brk(0x12349000)                         = 0x12349000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999270000
brk(0x1236b000)                         = 0x1236b000
brk(0x1238d000)                         = 0x1238d000
brk(0x123af000)                         = 0x123af000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9992ad000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9992ea000
brk(0x123d1000)                         = 0x123d1000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999327000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999364000
brk(0x123f3000)                         = 0x123f3000
brk(0x12416000)                         = 0x12416000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9993a1000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9993de000
brk(0x12438000)                         = 0x12438000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af99941b000
brk(0x1245a000)                         = 0x1245a000
brk(0x1247c000)                         = 0x1247c000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999458000
brk(0x1249e000)                         = 0x1249e000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999495000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9994d2000
brk(0x124c0000)                         = 0x124c0000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af99950f000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af99954c000
brk(0x124e2000)                         = 0x124e2000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999589000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9995c6000
brk(0x12504000)                         = 0x12504000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999603000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af999640000
brk(0x12526000)                         = 0x12526000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af99967d000
mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9996ba000
brk(0x12548000)                         = 0x12548000
brk(0x1256a000)                         = 0x1256a000
brk(0x1258c000)                         = 0x1258c000
brk(0x125ae000)                         = 0x125ae000
brk(0x125d0000)                         = 0x125d0000
brk(0x125f2000)                         = 0x125f2000
brk(0x12614000)                         = 0x12614000
mmap(NULL, , PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9996f7000
write(7, "\7?\0\0\6\0\0\0\0\0\3^&q\200\0\0\1\0\0\0\376\377\377\377\377\377\377\377y\0\0"..., 1855) = 1855
read(8, "\v\342\0\0\6\0\0\0\0\0\20\27\0\0\0\235\331\371\331\326\7G\332M\375\360_\360x\316jx"..., 8208) = 3042
brk(0x12636000)                         = 0x12636000
brk(0x12657000)                         = 0x12657000
brk(0x12678000)                         = 0x12678000
brk(0x12699000)                         = 0x12699000
brk(0x126bb000)                         = 0x126bb000
brk(0x126dc000)                         = 0x126dc000
brk(0x126fd000)                         = 0x126fd000
brk(0x1271e000)                         = 0x1271e000
brk(0x12740000)                         = 0x12740000
brk(0x12761000)                         = 0x12761000
brk(0x12782000)                         = 0x12782000
brk(0x127a3000)                         = 0x127a3000
brk(0x127c5000)                         = 0x127c5000
brk(0x127e6000)                         = 0x127e6000
brk(0x12807000)                         = 0x12807000
。。。。。略去幾十行的brk內容。。。

下面的日誌是降低buffer之後的,從直觀感受來說,日誌內容要少很多。
write(2, ". . exporting partition         "..., 54. . exporting partition                          A1_B1) = 54
brk(0x16ac7000)                         = 0x16ac7000
brk(0x16ae9000)                         = 0x16ae9000
brk(0x16b0b000)                         = 0x16b0b000
brk(0x16b2d000)                         = 0x16b2d000
brk(0x16b4f000)                         = 0x16b4f000
brk(0x16b71000)                         = 0x16b71000
write(7, "\7?\0\0\6\0\0\0\0\0\3^&q\200\0\0\1\0\0\0\376\377\377\377\377\377\377\377y\0\0"..., 1855) = 1855
read(8, "\v\342\0\0\6\0\0\0\0\0\20\27\0\0\0\235\331\371\331\326\7G\332M\375\360_\360x\316jx"..., 8208) = 3042
brk(0x16b92000)                         = 0x16b92000
brk(0x16bb3000)                         = 0x16bb3000
brk(0x16bd4000)                         = 0x16bd4000
brk(0x16bf5000)                         = 0x16bf5000
brk(0x16c17000)                         = 0x16c17000
brk(0x16c38000)                         = 0x16c38000
brk(0x16c59000)                         = 0x16c59000
brk(0x16c7a000)                         = 0x16c7a000
brk(0x16c9c000)                         = 0x16c9c000
brk(0x16cbd000)                         = 0x16cbd000
brk(0x16cde000)                         = 0x16cde000
brk(0x16cff000)                         = 0x16cff000
brk(0x16d21000)                         = 0x16d21000
brk(0x16d42000)                         = 0x16d42000
brk(0x16d63000)                         = 0x16d63000
brk(0x16d84000)                         = 0x16d84000
brk(0x16da6000)                         = 0x16da6000
brk(0x16dc7000)                         = 0x16dc7000
brk(0x16de8000)                         = 0x16de8000
brk(0x16e09000)                         = 0x16e09000
brk(0x16e2b000)                         = 0x16e2b000
brk(0x16e4c000)                         = 0x16e4c000
brk(0x16e6d000)                         = 0x16e6d000
brk(0x16e8e000)                         = 0x16e8e000
brk(0x16eb0000)                         = 0x16eb0000
brk(0x16ed1000)                         = 0x16ed1000
brk(0x16ef2000)                         = 0x16ef2000
brk(0x16f13000)                         = 0x16f13000
brk(0x16f35000)                         = 0x16f35000
brk(0x16f56000)                         = 0x16f56000
brk(0x16f77000)                         = 0x16f77000
brk(0x16f98000)                         = 0x16f98000
brk(0x16fba000)                         = 0x16fba000
brk(0x16fdb000)                         = 0x16fdb000
brk(0x16ffc000)                         = 0x16ffc000
lseek(3, 8192, SEEK_SET)                = 8192
read(3, "\r\0\307\0\0\0V\0\310\0\0\0\226\0\311\0\0\0\310\0\313\0\0\0\353\0\314\0\0\0\6\1"..., 512) = 512
write(2, "          0 rows exported", 25          0 rows exported) = 25
write(7, "\0V\0\0\6\0\0\0\0\0\21k'N\r\0\0+\0\0\0\1\0\0\0\3T(\376\377\377\377"..., 86) = 86
read(8, "\0\34\0\0\6\0\0\0\0\0\10N\r\0\0+\0\0\0\0\0\t\1\0\0\0\375\t", 8208) = 28
write(2, "\n", 1
)                       = 1
write(2, ". . exporting partition         "..., 54. . exporting partition                          A1_B2) = 54

對日誌琢磨了一番,發現了一個奇怪的情況,不知道是不是巧合。
表的欄位資訊如下,其中有number型別的欄位23個。在第一個很慢的日誌中。類似“mmap(NULL, 249856, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2af9992ad000”的內容就出現了23次。
 Nmae                                     Null?    Type          
------------------------------------- -------- --------------
OD_KEY                                NOT NULL NUMBER(5)     
ITION_ID                              NOT NULL NUMBER(5)     
T_ID                                  NOT NULL NUMBER(12)    
CREATION_DATE                         NOT NULL DATE          
UPDATE_DATE                                    DATE          
ATOR_ID                                        NUMBER(9)     
ICATION_ID                                     CHAR(6)       
ERVICE_CODE                                    CHAR(5)       
PDATE_STAMP                                    NUMBER(4)     
UNT_ID                                NOT NULL NUMBER(12)    
ING_ARRANGEMENT_ID                    NOT NULL NUMBER(12)    
ICE_ID                                         NUMBER(12)    
P_TYPE                                         VARCHAR2(6)   
GES_AMOUNT                                     NUMBER(18,2)  
AMOUNT                                         NUMBER(18,2)  
NCE                                            NUMBER(18,2)  
TION_DATE                                      DATE          
DATE                                           DATE          
SACTION_ID                                     NUMBER(12)    
_SEQ_NO                                        NUMBER(12)    
RITY                                           NUMBER(2)     
UTE_NET_AMOUNT                                 NUMBER(18,2)  
UTE_TAX_AMOUNT                                 NUMBER(18,2)  
ING_CREDIT_NET_AMOUNT                          NUMBER(18,2)  
ING_CREDIT_TAX_AMOUNT                          NUMBER(18,2)  
BILL_SEQ_NO                                    NUMBER(12)    
SUB_BILL_SEQ_NO                                NUMBER(12)    
ILL_SEQ_NO                                     NUMBER(12)    
UB_BILL_SEQ_NO                                 NUMBER(12)    
IOUS_LPF_CUTOFF_DATE                           DATE          
IOUS_LPF_START_DATE                            DATE          
ULATE_LPF_IND                                  CHAR(1)       
G_CATEGORY                                     CHAR(1)       
_TYPE                                          VARCHAR2(6)   
AST_LPF_CALC_DATE                              DATE          
PF_WAIVED_AMOUNT                               NUMBER(18,2)  

之前自己做過一個測試,把這個表的number欄位減少一些,速度就快了很多,和平時做的匯出就沒有任何區別了,可能問題的所在還是在number型欄位上。
oracle官方所給的關於buffer的解釋如下:

BUFFER

Default: operating system-dependent. See your Oracle operating system-specific documentation to determine the default value for this parameter.

Specifies the size, in bytes, of the buffer used to fetch rows. As a result, this parameter determines the maximum number of rows in an array fetched by Export. Use the following formula to calculate the buffer size:

buffer_size = rows_in_array * maximum_row_size

If you specify zero, then the Export utility fetches only one row at a time.

Tables with columns of type LOBs, LONG, BFILE, REF, ROWID, LOGICAL ROWID, or DATE are fetched one row at a time.

Note:

The BUFFER parameter applies only to conventional path Export. It has no effect on a direct path Export. For direct path Exports, use the RECORDLENGTH parameter to specify the size of the buffer that Export uses for writing to the export file.

Example: Calculating Buffer Size

This section shows an example of how to calculate buffer size.

The following table is created:

CREATE TABLE sample (name varchar(30), weight number);

The maximum size of the name column is 30, plus 2 bytes for the indicator. The maximum size of the weight column is 22 (the size of the internal representation for Oracle numbers), plus 2 bytes for the indicator.

Therefore, the maximum row size is 56 (30+2+22+2).

To perform array operations for 100 rows, a buffer size of 5600 should be specified.


如果說number的欄位值有多大,相比varchar2就小很多了。
個人感覺可能是一個bug.
至於為什麼buffer設定到9M匯出這個表就慢,到底慢在哪兒了?還可以透過strace來做一個很有意義的監控。

我們可以先執行exp的操作,讓它先慢慢執行,然後開啟strace,假設我們得到的exp的程式號是strace -c -p 25805
就可以透過strace -c -p 25805 來監控這個程式的一些詳細資訊。執行一會之後就強制中斷,得到的結果如下,97%以上的資源都耗在brk操作上了。
> strace -c -p 25805
Process 25805 attached - interrupt to quit


Process 25805 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.86    0.001054           6       186           brk
  2.14    0.000023           1        30           write
  0.00    0.000000           0        12           read
------ ----------- ----------- --------- --------- ----------------
100.00    0.001077                   228           total

brk的操作室返回記憶體管理的起始地址。比如brk(0x122e3000)                         = 0x122e3000 就是從0x122e3000 開始分配記憶體地址。
而如果調小buffer的部分,得到的日誌如下:
> strace -c -p 26025
Process 26025 attached - interrupt to quit
Process 26025 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 65.01    0.004096           3      1197           read
 34.99    0.002205           1      3522           write
------ ----------- ----------- --------- --------- ----------------
100.00    0.006301                  4719           total
可以看到都是讀寫操作,日誌裡面也確實匯出了不少的資料。

. . exporting partition                        A11_B10      65222 rows exported
. . exporting partition                         A12_B1     181825 rows exported
. . exporting partition                         A12_B2     181783 rows exported
. . exporting partition                         A12_B3     181582 rows exported

看來這個問題還是和number資料型別存在著一定的關係,大家在資料匯出的時候如果碰到這個問題也可以注意一下。

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/8494287/viewspace-1346975/,如需轉載,請註明出處,否則將追究法律責任。

相關文章