{"id":2939,"date":"2018-01-27T17:22:02","date_gmt":"2018-01-27T22:22:02","guid":{"rendered":"http:\/\/appcrawler.com\/wordpress\/?p=2939"},"modified":"2018-01-27T17:22:02","modified_gmt":"2018-01-27T22:22:02","slug":"spinlocks-does-oracle-use-them","status":"publish","type":"post","link":"http:\/\/appcrawler.com\/wordpress\/2018\/01\/27\/spinlocks-does-oracle-use-them\/","title":{"rendered":"Spinlocks, does Oracle use them?"},"content":{"rendered":"<p>I often write simple C programs to better understand how a given enterprise software program works.  Latches in the Oracle database are &#8220;in memory locks that protect critical sections of code&#8221;.  Oracle kernel developers decide that a given section of code should not be accessed by more than one session at a time, and protect access to it via a &#8220;latch&#8221;.  <\/p>\n<p>The question and purpose of this analysis is does Oracle use Linux operating system spinlocks to handle this?<\/p>\n<p>Below is a simple example of a spinlock in kernel 2.6.32.279&#8230;<\/p>\n<pre lang=\"c\" line=\"1\">\r\n#include<sys\/resource.h>\r\n#include<pthread.h>\r\n#include<stdio.h>\r\n\r\npthread_t tid[5];\r\nint counter;\r\npthread_spinlock_t spinlock;\r\n\r\nvoid* uselessCall() {\r\n  int l = pthread_spin_lock(&spinlock);\r\n  if (l == 0) {\r\n    printf(\"got spinlock\\n\");\r\n    sleep(10);\r\n    pthread_spin_unlock(&spinlock);\r\n    printf(\"released spinlock\\n\");\r\n  }\r\n  struct rusage r_usage;\r\n  getrusage(RUSAGE_SELF,&r_usage);\r\n  printf(\"User CPU time in seconds = %ld\\n\",r_usage.ru_utime.tv_sec);\r\n  printf(\"System CPU time in seconds = %ld\\n\",r_usage.ru_stime.tv_sec);\r\n}\r\n\r\nint main(void) {\r\n  int err;\r\n  int i = 0;\r\n\r\n  pthread_spin_init(&spinlock, counter);\r\n\r\n  for (i = 0 ; i < 5; i++) {\r\n    err = pthread_create(&#038;(tid[i]), NULL, &#038;uselessCall, NULL);\r\n  }\r\n\r\n  for (i = 0 ; i < 5; i++) {\r\n    pthread_join(tid[i], NULL);\r\n  }\r\n}\r\n<\/pre>\n<p>...which we then compile...<\/p>\n<pre lang=\"text\">\r\natllpecomodb01:oracle:atlecomp1:\/u01\/orahome>gcc -lpthread -o spin spin.c\r\n<\/pre>\n<p>...and finally run...<\/p>\n<pre lang=\"text\">\r\natllpecomodb01:oracle:atlecomp1:\/u01\/orahome>.\/spin\r\ngot spinlock\r\nreleased spinlock\r\ngot spinlock\r\nUser CPU time in seconds = 39\r\nSystem CPU time in seconds = 0\r\nreleased spinlock\r\nUser CPU time in seconds = 68\r\nSystem CPU time in seconds = 0\r\ngot spinlock\r\nreleased spinlock\r\nUser CPU time in seconds = 88\r\nSystem CPU time in seconds = 0\r\ngot spinlock\r\nreleased spinlock\r\nUser CPU time in seconds = 97\r\nSystem CPU time in seconds = 0\r\ngot spinlock\r\nreleased spinlock\r\nUser CPU time in seconds = 97\r\nSystem CPU time in seconds = 0\r\natllpecomodb01:oracle:atlecomp1:\/u01\/orahome>\r\n<\/pre>\n<p>Notice above that all CPU time occurs in user mode, as spinlock is not a system call.  You can also verify this by running an strace -f .\/spin.<\/p>\n<p>In oracle, we see very few system calls when a session is exhibiting high waits on latches.<\/p>\n<pre lang=\"java\" line=\"1\">\r\nimport java.sql.*;\r\nimport java.util.*;\r\n\r\npublic class testLatch implements Runnable {\r\n  public static void main (String args[]) {\r\n    try {\r\n      Class.forName(\"oracle.jdbc.driver.OracleDriver\");\r\n      for (int i = 1; i <= 4; i++) {\r\n        testLatch tl = new testLatch();\r\n      }\r\n    }\r\n    catch (Exception e) {\r\n    }\r\n  }\r\n\r\n  public testLatch() {\r\n    Thread t = new Thread(this);\r\n    t.start();\r\n  }\r\n\r\n  public void run() {\r\n    try {\r\n      Connection conn = DriverManager.getConnection(\"jdbc:oracle:thin:********\/*********@database_host:1521\/atlcatrwt.ecomm.local\");\r\n      Random r = new Random();\r\n      while (true) {\r\n        int i = r.nextInt();\r\n        Statement stm = conn.createStatement();\r\n        ResultSet rst = stm.executeQuery(\"select \" + i + \" from dual\");\r\n        rst.close();\r\n        stm.close();\r\n      }\r\n      \/\/conn.close();\r\n    }\r\n    catch (Exception e) {\r\n      e.printStackTrace();\r\n    }\r\n  }\r\n}\r\n<\/pre>\n<p>After compiling our class and running it (not shown above), we fetch one of our sessions OS PID, and run strace against it.<\/p>\n<pre lang=\"text\">\r\nroot@atllpecomodb01 Fri May 24 09:44:44 EDT 2013\r\n[~] # ps -ef | grep testLatch\r\noracle   30177 15019 38 09:43 pts\/0    00:01:42 java testLatch\r\nroot     32358 30903  0 09:48 pts\/1    00:00:00 grep testLatch\r\n\r\nroot@atllpecomodb01 Fri May 24 09:44:44 EDT 2013\r\n[~] # ps -ef | grep LOCAL | grep 09:43\r\noracle   30203     1 75 09:43 ?        00:03:29 oracleatlecomt1 (LOCAL=NO)\r\noracle   30206     1 78 09:43 ?        00:03:38 oracleatlecomt1 (LOCAL=NO)\r\noracle   30209     1 78 09:43 ?        00:03:38 oracleatlecomt1 (LOCAL=NO)\r\noracle   30211     1 78 09:43 ?        00:03:37 oracleatlecomt1 (LOCAL=NO)\r\n\r\n[~] # time strace -f -p 30203 -c\r\nProcess 30203 attached - interrupt to quit\r\n^CProcess 30203 detached\r\n% time     seconds  usecs\/call     calls    errors syscall\r\n------ ----------- ----------- --------- --------- ----------------\r\n 46.34    0.004258           0      9948           write\r\n 27.72    0.002547           0      9949           read\r\n 10.72    0.000985           0    159179           times\r\n  9.81    0.000901           0    169122           getrusage\r\n  3.34    0.000307           0      1816           semctl\r\n  2.08    0.000191           0      1646           semop\r\n  0.00    0.000000           0       265           sched_yield\r\n  0.00    0.000000           0        62        53 semtimedop\r\n------ ----------- ----------- --------- --------- ----------------\r\n100.00    0.009189                351987        53 total\r\n\r\nreal    0m18.407s\r\nuser    0m1.650s\r\nsys     0m4.845s\r\n\r\nroot@atllpecomodb01 Fri May 24 09:44:44 EDT 2013\r\n[~] #\r\n<\/pre>\n<p>We run strace for about 18 seconds, which is comprised of under 5 seconds of system CPU time.  We also see the actual calls that led up to that total, almost all of which is not semaphore related.<\/p>\n<p>This does not necessarily mean that Oracle does not use spinlocks.  However, 13 seconds of non-CPU time also does not show up in user time as it did when we ran our simple C language test earlier in this post.<\/p>\n<p>However, our java test is flawed.  The network time to execute the selects is killing us.  Let's rewrite it to use an anonymous PL\/SQL block that issues the selects \"internally\" in the database.<\/p>\n<p>Next, we'll check our calls using ltrace.  This is similar to strace, only it traces calls in user space.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>I often write simple C programs to better understand how a given enterprise software program works. Latches in the Oracle database are &#8220;in memory locks that protect critical sections of code&#8221;. Oracle kernel developers decide that a given section of&hellip;<\/p>\n<p class=\"more-link-p\"><a class=\"more-link\" href=\"http:\/\/appcrawler.com\/wordpress\/2018\/01\/27\/spinlocks-does-oracle-use-them\/\">Read more &rarr;<\/a><\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_mi_skip_tracking":false,"footnotes":""},"categories":[28,27],"tags":[],"_links":{"self":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/2939"}],"collection":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/comments?post=2939"}],"version-history":[{"count":19,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/2939\/revisions"}],"predecessor-version":[{"id":6612,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/2939\/revisions\/6612"}],"wp:attachment":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/media?parent=2939"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/categories?post=2939"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/tags?post=2939"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}