I often write simple C programs to better understand how a given enterprise software program works. Latches in the Oracle database are “in memory locks that protect critical sections of code”. 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 “latch”.
The question and purpose of this analysis is does Oracle use Linux operating system spinlocks to handle this?
Below is a simple example of a spinlock in kernel 2.6.32.279…
#include
#include
#include
pthread_t tid[5];
int counter;
pthread_spinlock_t spinlock;
void* uselessCall() {
int l = pthread_spin_lock(&spinlock);
if (l == 0) {
printf("got spinlock\n");
sleep(10);
pthread_spin_unlock(&spinlock);
printf("released spinlock\n");
}
struct rusage r_usage;
getrusage(RUSAGE_SELF,&r_usage);
printf("User CPU time in seconds = %ld\n",r_usage.ru_utime.tv_sec);
printf("System CPU time in seconds = %ld\n",r_usage.ru_stime.tv_sec);
}
int main(void) {
int err;
int i = 0;
pthread_spin_init(&spinlock, counter);
for (i = 0 ; i < 5; i++) {
err = pthread_create(&(tid[i]), NULL, &uselessCall, NULL);
}
for (i = 0 ; i < 5; i++) {
pthread_join(tid[i], NULL);
}
}
...which we then compile...
atllpecomodb01:oracle:atlecomp1:/u01/orahome>gcc -lpthread -o spin spin.c
...and finally run...
atllpecomodb01:oracle:atlecomp1:/u01/orahome>./spin
got spinlock
released spinlock
got spinlock
User CPU time in seconds = 39
System CPU time in seconds = 0
released spinlock
User CPU time in seconds = 68
System CPU time in seconds = 0
got spinlock
released spinlock
User CPU time in seconds = 88
System CPU time in seconds = 0
got spinlock
released spinlock
User CPU time in seconds = 97
System CPU time in seconds = 0
got spinlock
released spinlock
User CPU time in seconds = 97
System CPU time in seconds = 0
atllpecomodb01:oracle:atlecomp1:/u01/orahome>
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.
In oracle, we see very few system calls when a session is exhibiting high waits on latches.
import java.sql.*;
import java.util.*;
public class testLatch implements Runnable {
public static void main (String args[]) {
try {
Class.forName("oracle.jdbc.driver.OracleDriver");
for (int i = 1; i <= 4; i++) {
testLatch tl = new testLatch();
}
}
catch (Exception e) {
}
}
public testLatch() {
Thread t = new Thread(this);
t.start();
}
public void run() {
try {
Connection conn = DriverManager.getConnection("jdbc:oracle:thin:********/*********@database_host:1521/atlcatrwt.ecomm.local");
Random r = new Random();
while (true) {
int i = r.nextInt();
Statement stm = conn.createStatement();
ResultSet rst = stm.executeQuery("select " + i + " from dual");
rst.close();
stm.close();
}
//conn.close();
}
catch (Exception e) {
e.printStackTrace();
}
}
}
After compiling our class and running it (not shown above), we fetch one of our sessions OS PID, and run strace against it.
root@atllpecomodb01 Fri May 24 09:44:44 EDT 2013
[~] # ps -ef | grep testLatch
oracle 30177 15019 38 09:43 pts/0 00:01:42 java testLatch
root 32358 30903 0 09:48 pts/1 00:00:00 grep testLatch
root@atllpecomodb01 Fri May 24 09:44:44 EDT 2013
[~] # ps -ef | grep LOCAL | grep 09:43
oracle 30203 1 75 09:43 ? 00:03:29 oracleatlecomt1 (LOCAL=NO)
oracle 30206 1 78 09:43 ? 00:03:38 oracleatlecomt1 (LOCAL=NO)
oracle 30209 1 78 09:43 ? 00:03:38 oracleatlecomt1 (LOCAL=NO)
oracle 30211 1 78 09:43 ? 00:03:37 oracleatlecomt1 (LOCAL=NO)
[~] # time strace -f -p 30203 -c
Process 30203 attached - interrupt to quit
^CProcess 30203 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
46.34 0.004258 0 9948 write
27.72 0.002547 0 9949 read
10.72 0.000985 0 159179 times
9.81 0.000901 0 169122 getrusage
3.34 0.000307 0 1816 semctl
2.08 0.000191 0 1646 semop
0.00 0.000000 0 265 sched_yield
0.00 0.000000 0 62 53 semtimedop
------ ----------- ----------- --------- --------- ----------------
100.00 0.009189 351987 53 total
real 0m18.407s
user 0m1.650s
sys 0m4.845s
root@atllpecomodb01 Fri May 24 09:44:44 EDT 2013
[~] #
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.
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.
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.
Next, we'll check our calls using ltrace. This is similar to strace, only it traces calls in user space.