{"id":1489,"date":"2009-04-22T12:00:00","date_gmt":"2009-04-22T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1489"},"modified":"2009-04-22T12:00:00","modified_gmt":"2009-04-22T12:00:00","slug":"how-to-induce-log-file-sync-waits","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2009\/04\/22\/how-to-induce-log-file-sync-waits\/","title":{"rendered":"How to induce log file sync waits"},"content":{"rendered":"

(With my tongue causing a minor gash on the inside of my cheek ….)<\/p>\n

I’m working on an application that seems to suffer constant long waits on log file parallel write and, consequently, log file sync. I thought that the 54 ms log file parallel writes where just typical of an early 90s disk configuration, with each file type on a discrete drive, all attached to the same controller and it was timely, given a blog post I read recently<\/a>.<\/p>\n

But no, let’s not just slow up the I\/O, let’s make sure we generate lots of it! I noticed that these two procedures were some of the most frequently executed.<\/p>\n

PROCEDURE RL_addLock (\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockEntity IN d000m.lock_entity_no%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockEntityKey IN d000m.lock_entity_key%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockProfileId IN d000m.lock_profile_id%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockSessionNo IN d000m.lock_session_no%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockOperatorId IN d000m.lock_operator_id%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockTaskId IN d000m.lock_task_id%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockDate IN d000m.lock_date%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockTime IN d000m.lock_time%TYPE\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 )\nIS\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 PRAGMA AUTONOMOUS_TRANSACTION;\nBEGIN\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 INSERT INTO d000m\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 VALUES (lockEntity,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockEntityKey,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockProfileId,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockSessionNo,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockOperatorId,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockTaskId,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockDate,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockTime\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 );\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 COMMIT;\nEXCEPTION\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 WHEN DUP_VAL_ON_INDEX THEN\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 BEGIN\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ROLLBACK;\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 END;\nEND;\n\/\n\nPROCEDURE RL_delLock (\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockEntity IN d000m.lock_entity_no%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockEntityKey IN d000m.lock_entity_key%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockProfileId IN d000m.lock_profile_id%TYPE,\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 lockSessionNo IN d000m.lock_session_no%TYPE\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 )\nIS\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 PRAGMA AUTONOMOUS_TRANSACTION;\nBEGIN\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 DELETE FROM d000m\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 WHERE lock_entity_no = lockEntity\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 AND lock_entity_key = lockEntityKey\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 AND lock_profile_id = lockProfileId\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 AND lock_session_no = lockSessionNo;\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 COMMIT;\nEXCEPTION\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 WHEN NO_DATA_FOUND THEN\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 BEGIN\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 ROLLBACK;\n\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 END;\nEND;\n\/<\/pre>\n
Excellent. Yet another developer implementing their own locking architecture, presumably to make their application database independent. Yes, it is common, but having just moaned about this kind of thing in the footnote to a previous blog post<\/a> …<\/p>\n
“Why am I still seeing locking problems? I think it’s
\nbecause I often have to support Third-Party “Database-independent”
\n(yuck!) applications, some of which insist on implementing their own
\nlocking mechanisms. Sigh.”<\/em>
…this one sent me over the edge.<\/p>\n","protected":false},"excerpt":{"rendered":"
(With my tongue causing a minor gash on the inside of my cheek ….) I’m working on an application that seems to suffer constant long waits on log file parallel write and, consequently, log file sync. I thought that the 54 ms log file parallel writes where just typical of an early 90s disk configuration,… Continue reading How to induce log file sync waits<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[],"class_list":["post-1489","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1156,"url":"http:\/\/orcldoug.com\/blog\/2006\/12\/07\/a-more-complex-statspack-example-part-2\/","url_meta":{"origin":1489,"position":0},"title":"A More Complex Statspack Example – Part 2","date":"December 7, 2006","format":false,"excerpt":"So far we're barely into the comparison of the Statspack reports from the two different test environments and they look quite different already.Next up, the Instance Efficiency Percentages. I have to confess that I rarely find these very useful because the numbers are always near 100% on most databases I\u2026","rel":"","context":"With 13 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1428,"url":"http:\/\/orcldoug.com\/blog\/2008\/08\/14\/time-matters-an-infinite-capacity-for-waiting\/","url_meta":{"origin":1489,"position":1},"title":"Time Matters – An Infinite Capacity for Waiting*","date":"August 14, 2008","format":false,"excerpt":"When I was teaching the 10g Performance class at my last customer site, I remarked that the total number of seconds you see in the \"Top 5 Timed Events\" section of a Statspack or AWR report will often be greater than the total number of seconds between the snapshot intervals.\u2026","rel":"","context":"With 6 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1612,"url":"http:\/\/orcldoug.com\/blog\/2010\/09\/12\/that-pictures-demo-in-full\/","url_meta":{"origin":1489,"position":2},"title":"That Pictures demo in full","date":"September 12, 2010","format":false,"excerpt":"Note - features in this post require the Diagnostics Pack licenseWith so many potential technical posts in my pile, it was initially difficult to decide where to start again but I figured I should avoid the stats series until I'm back into the swing of things \ud83d\ude09 Instead I decided\u2026","rel":"","context":"With 6 comments","img":{"alt_text":"","src":"https:\/\/i0.wp.com\/18.133.199.212\/wp-content\/uploads\/recovered\/pic_demo9.png?resize=350%2C200","width":350,"height":200},"classes":[]},{"id":1585,"url":"http:\/\/orcldoug.com\/blog\/2010\/03\/11\/hotsos-2010-day-4\/","url_meta":{"origin":1489,"position":3},"title":"Hotsos 2010 – Day 4","date":"March 11, 2010","format":false,"excerpt":"First up was Cary Millsap's - Lessons Learned, Version 2010.03 As Cary pointed out, they always try to put the best speakers in the toughest slots - 8:30 in the morning post-party. I think local guys are slightly more reliable too because they might have actually gone home the night\u2026","rel":"","context":"With 10 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1574,"url":"http:\/\/orcldoug.com\/blog\/2010\/03\/07\/hotsos-2010-my-agenda\/","url_meta":{"origin":1489,"position":4},"title":"Hotsos 2010 – My Agenda","date":"March 7, 2010","format":false,"excerpt":"Let's see how well I can stick to thisSunday18:00 - Registration and Reception21:00 - BedMonday09:45 - Tom Kyte: All About Metadata: Why Telling the Database about Your Schema Matters\u00a0 \u00a011:00 - Richard Foote: Oracle Indexing Myths12:00 - Lunch (make sure new laptop works with projector, get changed and start panicking\u2026","rel":"","context":"With 1 comment","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1613,"url":"http:\/\/orcldoug.com\/blog\/2010\/09\/19\/alternative-pictures-demo\/","url_meta":{"origin":1489,"position":5},"title":"Alternative Pictures Demo","date":"September 19, 2010","format":false,"excerpt":"Note - features in this post require the Diagnostics Pack licenseNot long after I'd finished the last post, I realised I could reinforce the points I was making with a quick post showing another one of the example tests supplied with Swingbench - the Calling Circle (CC) application. Like the\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"https:\/\/i0.wp.com\/18.133.199.212\/wp-content\/uploads\/recovered\/190910_1.png?resize=350%2C200","width":350,"height":200},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1489","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/comments?post=1489"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1489\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1489"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1489"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1489"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}