oracle pl/sql 存储过程...执行时间去哪了？
声明：本页面是StackOverFlow热门问题的中英对照翻译，遵循CC BY-SA 4.0协议，如果您需要使用它，必须同样遵循CC BY-SA许可，注明原文地址和作者信息，同时你必须将它归于原作者（不是我）：StackOverFlow
原文地址: http://stackoverflow.com/questions/1050180/
Warning: these are provided under cc-by-sa 4.0 license. You are free to use/share it, But you must attribute it to the original authors (not me):
StackOverFlow
pl/sql Stored procedure... where does the execution time go?
提问by PeterP
I am currently tracing a performance leak in a stored procedure. Having a timestamp put out right after the initial "begin" and one right before the final "end" (I am doing a commit before) says the procedure takes abt. 10 secs to finish. However, I have to wait 2mins+ for it to end.
我目前正在跟踪存储过程中的性能泄漏。在最初的“开始”之后和最终“结束”之前（我正在提交之前）有一个时间戳，表示该过程需要abt。10秒完成。但是，我必须等待 2 分钟以上才能结束。
Can anybody tell me where the rest of the times goes? I am using Oracle SQL dev but It doesn't seem to be idleing for the rest of the time, the procedure seems to hold a lock on the respective table :(
谁能告诉我剩下的时间都去哪儿了？我正在使用 Oracle SQL dev 但它似乎在其余时间没有空闲，该过程似乎在相应的表上持有锁:(
Thanks a lot in advance for enlightening....
非常感谢您的启发......
EDIT:thanks again for your input :) here's the stripped code for the procedure, depending on the number of items to be processed, the 1st section currently takes abt. 10 to 40 seconds, the 2nd section a few millisecs. however the procedure takes 2 to 8 mins to run. also, the table containing the data to delete seem to be locked somewhat longer than needed, causing inserts to be deferred. starting it as scheduled job makes no difference btw, same behavior.
编辑：再次感谢您的输入 :) 这里是程序的剥离代码，取决于要处理的项目数量，第一部分当前需要 abt。10到40秒，第二段几毫秒。但是，该过程需要 2 到 8 分钟才能运行。此外，包含要删除的数据的表似乎被锁定的时间比所需的时间长，从而导致插入被推迟。顺便说一句，将其作为预定作业启动没有区别，相同的行为。
create or replace
procedure MY_PROCEDURE is
start_procedure number;
start_delete number;
end_procedure number;
begin
start_procedure :=dbms_utility.get_time;
begin
-- stripped: doing some selects/updates here
end;
commit;
start_delete :=dbms_utility.get_time ;
begin
-- stripped: cleanig up some other data here
end;
commit;
end_procedure :=dbms_utility.get_time ;
dbms_output.put_line('procedure took: '||to_char((end_procedure- start_procedure)/1000));
dbms_output.put_line('updates took: '||to_char((start_delete- start_procedure)/1000));
dbms_output.put_line('delete took: '||to_char((end_procedure-start_delete)/1000));
end;
采纳答案by PeterP
Problem solved, but I still do not understand...
问题解决了，还是没看懂。。。
The leak was caused by a bad select statement buried in another procedure which is called by the other procedure. I optimized it, now it runs like charm.
泄漏是由隐藏在另一个过程中的错误选择语句引起的，该过程被另一个过程调用。我优化了它，现在它运行起来很有魅力。
I found out the hard way, commenting line by line... trying and trying.
我发现了困难的方法，逐行评论......尝试和尝试。
However, I'd still like to know why the timestamps were absolutely inaccurate. This was very misleading and cost me quite some time... So, is there anything wrong with the way I create the timestamps?
但是，我仍然想知道为什么时间戳绝对不准确。这是非常具有误导性的，并花费了我相当长的时间......那么，我创建时间戳的方式有什么问题吗？
If anyone has info on this, I'd be glad to hear it.
如果有人有这方面的信息，我会很高兴听到。
Thanks to all of you for your help with this issue.
感谢大家对这个问题的帮助。
回答by Plasmer
I think you need to be dividing by 100, not 1000(dbms_utility.get_time gives time in centiseconds). That should give you 100 seconds, which is about 2 minutes.
我认为您需要除以 100，而不是 1000（dbms_utility.get_time 以厘秒为单位给出时间）。这应该给你 100 秒，大约 2 分钟。
However, if you're interested in finding out where the 2 minutes of execution time went, and depending on the complexity of the procedure, you may want to either:
但是，如果您有兴趣找出 2 分钟执行时间的去向，并且根据过程的复杂性，您可能想要：
- collect a statspack report by taking snapshots before and after the procedure runs
- use the PL/SQL Hierarchical Profiler(http://download.oracle.com/docs/cd/B28359_01/appdev.111/b28424/adfns_profiler.htm#CHDCIGIB).
- 通过在程序运行之前和之后拍摄快照来收集 statspack 报告
- 使用 PL/SQL 分层分析器（http://download.oracle.com/docs/cd/B28359_01/appdev.111/b28424/adfns_profiler.htm#CHDCIGIB）。
The profiler may be better if you have a lot of chained PL/SQL procedure calls. The statspack report will be better if you have mostly sql statements inside the stored procedure.
如果您有大量链式 PL/SQL 过程调用，则探查器可能会更好。如果存储过程中主要是 sql 语句，则 statspack 报告会更好。
Here's what the Profiler output looks like:
下面是 Profiler 输出的样子：
Sample Report
Function Elapsed Time (microsecs) Data sorted by Total Subtree Elapsed Time (microsecs)
2831 microsecs (elapsed time) & 12 function calls
Subtree Ind% Function Descendant Ind% Calls Ind% Function Name
2831 100% 93 2738 96.7% 2 16.7% __plsq_vm
2738 96.7% 310 2428 85.8% 2 16.7% __anonymous_block
2428 85.8% 15 2413 85.2% 1 8.3% HR.TEST.TEST (Line 1)
2413 85.2% 435 1978 69.9% 3 25.0% HR.TEST.TEST.FOO (Line 3)
1978 69.9% 1978 0 0.0% 3 25.0% HR.TEST.__static_sql_exec_line5 (Line 5)
0 0.0% 0 0 0.0% 1 8.3% SYS.DBMS_HPROF.STOP_PROFILING (Line 53)
回答by Tony Andrews
If you replace those calls to dbms_utility.get_time by messages like:
如果您将这些对 dbms_utility.get_time 的调用替换为以下消息：
dbms_output.put_line ('start procedure: ' || to_char(sysdate, HH24:MI:SS'));
and then call the procedure like this:
然后像这样调用程序：
dbms_output.put_line ('before procedure: ' || to_char(sysdate, HH24:MI:SS'));
exec my_procedure;
dbms_output.put_line ('after procedure: ' || to_char(sysdate, HH24:MI:SS'));
then the place where the missing time occurs will show up.
那么出现时间缺失的地方就会出现。
回答by Mike Dunlavey
I'm not familiar with pl/sql, but is there a way to pause or interrupt it while it's running?
我不熟悉 pl/sql，但是有没有办法在它运行时暂停或中断它？
The chance that you will hit it while it's being wasteful is equal to the percent of time it's wasting, so you may need to stop it several times to catch it in the act. Often the problem is somewhere in the middle of the call stack. Anything that appears on more than one stack sample will, if you can replace it, save you significant time.
你在它浪费的时候击中它的机会等于它浪费的时间的百分比，所以你可能需要多次停止它才能在行动中抓住它。通常问题出在调用堆栈中间的某个地方。出现在多个堆栈示例上的任何内容（如果您可以替换它）都会为您节省大量时间。
回答by dub
There might be something in the declaration section that is taking long to execute. Could you include the code of your stored procedure ?
声明部分中的某些内容可能需要很长时间才能执行。你能包括你的存储过程的代码吗？
回答by prof401
In your DBMS_OUTPUT statements you are dividing your result by 1000. According to all the Oracle documenation I can find on the dbms_utility.get_time function measure time in 100ths of seconds, not 1000ths.
在您的 DBMS_OUTPUT 语句中，您将结果除以 1000。根据我可以在 dbms_utility.get_time 函数中找到的所有 Oracle 文档，以 100ths of seconds 而不是 1000ths 为单位测量时间。
So while you are displaying 10 to 40 seconds, it is actually 100 (1 minute 40 seconds) to 400 (6 minutes 40 seconds) seconds. This is more inline with the 2 to 8 minutes you are observing.
因此，当您显示 10 到 40 秒时，实际上是 100（1 分 40 秒）到 400（6 分 40 秒）秒。这更符合您观察的 2 到 8 分钟。
Check out http://download-west.oracle.com/docs/cd/B19306_01/appdev.102/b14258/d_util.htmfor more information on the function.
查看http://download-west.oracle.com/docs/cd/B19306_01/appdev.102/b14258/d_util.htm了解有关该功能的更多信息。
回答by Jim Hudson
Oracle contains a profiler that will tell you the amount of time spent on each executable statement. dbms_profiler for 10g and earlier, and there's a fancier version (the hierarchical profiler) available in 11g.
Oracle 包含一个分析器，它会告诉您在每个可执行语句上花费的时间量。dbms_profiler 适用于 10g 及更早版本，11g 中提供了更高级的版本（分层分析器）。
Much simpler than using sets of dbms_utility and dbms_output statements, and it gives you much more complete information -- including drilldown into the called routines if you have rights to see their source code.
比使用 dbms_utility 和 dbms_output 语句集简单得多，并且它为您提供了更完整的信息——包括深入到被调用例程（如果您有权查看它们的源代码）。
I'm glad you solved your problem. Next time, though, using the profiler will make it easier.
我很高兴你解决了你的问题。不过，下次使用分析器会更容易。
回答by Gary Myers
What does the procedure do ? One possible explanation may be DBMS_OUTPUT. If, on SQL*Plus, you do a SET SERVEROUTPUT ON, after a statement has executed, the client does a 'behind-the-scenes' fetch of any information that has been buffered using DBMS_OUTPUT.PUT_LINE. I'd guess SQL Developer does the same.
程序有什么作用？一种可能的解释可能是 DBMS_OUTPUT。如果在 SQL*Plus 上执行 SET SERVEROUTPUT ON，则在语句执行后，客户端会对使用 DBMS_OUTPUT.PUT_LINE 缓冲的任何信息进行“幕后”提取。我猜 SQL Developer 也是如此。
So if a lot of stuff has been pushed to DBMS_OUTPUT, then the execution of the procedure could be quick, but the behind-the-scenes collection of that could be taking up the time (especially if it is a slow network).
所以如果很多东西都被推送到 DBMS_OUTPUT，那么过程的执行可能很快，但是幕后收集可能会占用时间（特别是如果它是一个缓慢的网络）。
Another trick in SQL*Plus is you can SET TIMING ON (which will automatically show the elapsed time of the statement) and SET TIME ON (which shows the time in the SQL prompt).
SQL*Plus 中的另一个技巧是您可以 SET TIMING ON（它会自动显示语句的经过时间）和 SET TIME ON（它在 SQL 提示中显示时间）。
So try
所以试试
SET SERVEROUTPUT OFF
SET TIMING ON
SET TIME ON
DBMS_MONITOR.DATABASE_TRACE_ENABLE(TRUE);
exec stored_proc;
disconn
And see the results. I wouldn't expect to see any time unaccounted for. That is, the client should report the full two minutes. Assuming it does, I'd be using the trace (the DBMS_MONITOR command) and run a tkprof on the result to see what accounts for those 2 minutes.
并查看结果。我不希望看到任何下落不明的时间。也就是说，客户端应该报告完整的两分钟。假设确实如此，我将使用跟踪（DBMS_MONITOR 命令）并对结果运行 tkprof 以查看这 2 分钟的原因。
回答by Tom S
Your time is probably due to a large number of context switches between java and the database as SQL developer refreshes your screen. to test this, run your test again in SQLPlus. To fix, go into tools > preferences > database > advanced Parameters and up your SQL Array Fetch Size to a value somewhere between 150 and 500, and (if you have appropriate drivers) check off the Use OCI/Thick driver box.
您的时间可能是由于 SQL 开发人员刷新您的屏幕时在 Java 和数据库之间进行了大量上下文切换。要对此进行测试，请在 SQLPlus 中再次运行您的测试。要修复，请进入工具 > 首选项 > 数据库 > 高级参数并将 SQL 数组提取大小提高到 150 到 500 之间的某个值，然后（如果您有合适的驱动程序）选中使用 OCI/厚驱动程序框。
回答by akf
if you have the appropriate perms (and if not, ask your dba for help) perhaps you could query the following views:
如果您有适当的权限（如果没有，请向您的 dba 寻求帮助）也许您可以查询以下视图：
V$SESSION_WAIT
V$SYSTEM_EVENT
you can then check the results
然后你可以检查结果
here (http://www.remote-dba.net/oracle_10g_tuning/t_oracle_v$session_wait.htm)* is a description on how to read the output, and here is some more infoon the events inside.
这里 ( http://www.remote-dba.net/oracle_10g_tuning/t_oracle_v$session_wait.htm)* 是关于如何读取输出的描述，这里是关于内部事件的更多信息。
* you will have to copy the url as the $ is messing up the link.
* 您必须复制网址，因为 $ 会弄乱链接。
