Stormsail

Ooo, a new family member Sarah Mae Lawrence popped out today, and a shame that I was on holiday at the time. Welcome to the family little one.

I recently had a case with a customer concerned over the time taken to dd an Oracle redo log file even though Oracle had been shutdown. Finding this strange I thought I’d use TNF probes to see what was happening.

#!/bin/sh -x
# Script to collect TNF data whilst dd is happening on Oracle log file
#
# Andy H 19/09/06
#
TMPDIR=${TMPDIR:-/var/tmp/tnf}
output_file=$TMPDIR/ktrace.tnf
command="dd if=/u01/oracle/oradata/TEST/redo01.log of=/u01/oracle/oradata/TEST/tmp.tmp"
start_prex()
{
echo "Enabling kernel tracing"
prex -k <<EOF
buffer alloc 130m
enable \$all
trace \$all
ktrace on
quit
EOF
}
stop_prex()
{
prex -k <<EOF
ktrace off
buffer dealloc
quit
EOF
echo "Kernel tracing disabled"
}
run_command() {
if [ "$command" ]; then
$command &
pid=$!
echo $pid > $TMPDIR/pid.out
wait $pid
fi
}
# Extract kernel trace buffer
ktrace_xtract() {
echo "Extracting kernel trace buffer"
tnfxtract $output_file || fail "Could not extract kernel trace buffer"
ls -l $output_file
}
# Get kernel symbols
ktrace_sym() {
echo "Collecting kernel symbol information"
/usr/ccs/bin/nm -fx /dev/ksyms | tr "|" " " > $TMPDIR/nm.out
}
# tar and gzip data
ktrace_gzip() {
echo "Packaging collected data"
/usr/sbin/tar cf /tmp/tnf.tar $TMPDIR
/usr/bin/gzip /tmp/tnf.tar
echo "Collection complete, please send in /tmp/tnf.tar.gz for analysis"
}
start_prex
run_command
ktrace_xtract
ktrace_sym
stop_prex
ktrace_gzip

Following using some clever sorting awk script from Tim Uglow I compared the TNF output from the normal dd timing and then the slow one.

64.922000  -  2562 1 0x300042edc20 0 page_unmap vnode: 0x600062ee440 offset: 157253632
64.924500  -  2562 1 0x300042edc20 0 page_unmap vnode: 0x600062ee440 offset: 157261824
64.927100  -  2562 1 0x300042edc20 0 page_unmap vnode: 0x600062ee440 offset: 157270016
64.929200  -  2562 1 0x300042edc20 0 page_unmap vnode: 0x600062ee440 offset: 157278208
64.931500  -  2562 1 0x300042edc20 0 page_unmap vnode: 0x600062ee440 offset: 157286400
101.904300  -  2562 1 0x300042edc20 0 syscall_end rval1: 4 rval2: 0 errno: 0 creat64 98.822400 No error
101.908200  -  2562 1 0x300042edc20 0 thread_queue tid: 0x300042edc20 cpuid: 0 priority: 0 queue_length: 0x0
101.908500  -  2562 1 0x300042edc20 0 thread_state tid: 0x300042edc20 state: 8 waiting for CPU
101.924000  -  2562 1 0x300042edc20 0 syscall_start sysnum: 137 sysconfig
101.924500  -  2562 1 0x300042edc20 0 syscall_end rval1: 8192 rval2: 18466816 errno: 0 sysconfig 0.000500 No error
101.928700  -  2562 1 0x300042edc20 0 syscall_start sysnum: 17 brk
101.931200  -  2562 1 0x300042edc20 0 syscall_end rval1: 0 rval2: 134217728 errno: 0 brk 0.002500 No error
101.932500  -  2562 1 0x300042edc20 0 syscall_start sysnum: 17 brk
101.941300  -  2562 1 0x300042edc20 0 syscall_end rval1: 0 rval2: 134217728 errno: 0 brk 0.008800 No error
101.943200  -  2562 1 0x300042edc20 0 thread_state state: 4 asleep in user data fault
101.945400  -  2562 1 0x300042edc20 0 address_fault address: 0x28000 fault_type: 0 access: 1
101.947900  -  2562 1 0x300042edc20 0 anon_zero address: 0x28000
101.967700  -  2562 1 0x300042edc20 0 thread_state state: 0 in userland
101.978500  -  2562 1 0x300042edc20 0 syscall_start sysnum: 98 sigaction
101.980600  -  2562 1 0x300042edc20 0 syscall_end rval1: 0 rval2: 0 errno: 0 sigaction 0.002100 No error
101.985800  -  2562 1 0x300042edc20 0 syscall_start sysnum: 3 read
102.000000  -  2562 1 0x300042edc20 0 syscall_end rval1: 512 rval2: 8193 errno: 0 read 0.014200 No error
102.009800  -  2562 1 0x300042edc20 0 syscall_start sysnum: 4 write
102.073000  -  2562 1 0x300042edc20 0 syscall_end rval1: 512 rval2: 8962 errno: 0 write 0.063200 No error
102.074500  -  2562 1 0x300042edc20 0 syscall_start sysnum: 3 read
102.079700  -  2562 1 0x300042edc20 0 syscall_end rval1: 512 rval2: 8193 errno: 0 read 0.005200 No error
102.082300  -  2562 1 0x300042edc20 0 syscall_start sysnum: 4 write
102.088200  -  2562 1 0x300042edc20 0 syscall_end rval1: 512 rval2: 8962 errno: 0 write 0.005900 No error
102.089200  -  2562 1 0x300042edc20 0 syscall_start sysnum: 3 read
102.093600  -  2562 1 0x300042edc20 0 syscall_end rval1: 512 rval2: 8193 errno: 0 read 0.004400 No error
102.096200  -  2562 1 0x300042edc20 0 syscall_start sysnum: 4 write
102.129600  -  2562 1 0x300042edc20 0 syscall_end rval1: 512 rval2: 8962 errno: 0 write 0.033400 No error
102.130900  -  2562 1 0x300042edc20 0 syscall_start sysnum: 3 read
102.136100  -  2562 1 0x300042edc20 0 syscall_end rval1: 512 rval2: 8193 errno: 0 read 0.005200 No error
102.138600  -  2562 1 0x300042edc20 0 syscall_start sysnum: 4 write

So each of the read() / writes() happen one after each other…..but what about on the so called broken one:

59.433900  -  2635 1 0x300041792c0 3 page_unmap vnode: 0x600062ee440 offset: 157253632
59.436200  -  2635 1 0x300041792c0 3 page_unmap vnode: 0x600062ee440 offset: 157261824
59.438300  -  2635 1 0x300041792c0 3 page_unmap vnode: 0x600062ee440 offset: 157270016
59.440300  -  2635 1 0x300041792c0 3 page_unmap vnode: 0x600062ee440 offset: 157278208
59.442600  -  2635 1 0x300041792c0 3 page_unmap vnode: 0x600062ee440 offset: 157286400
95.378500  -  2635 1 0x300041792c0 3 syscall_end rval1: 4 rval2: 0 errno: 0 creat64 91.600000 No error
95.380600  -  2635 1 0x300041792c0 3 thread_queue tid: 0x300041792c0 cpuid: 3 priority: 0 queue_length: 0x0
95.380800  -  2635 1 0x300041792c0 3 thread_state tid: 0x300041792c0 state: 8 waiting for CPU
95.398100  -  2635 1 0x300041792c0 3 syscall_start sysnum: 137 sysconfig
95.398600  -  2635 1 0x300041792c0 3 syscall_end rval1: 8192 rval2: 18466816 errno: 0 sysconfig 0.000500 No error
95.404300  -  2635 1 0x300041792c0 3 syscall_start sysnum: 17 brk
95.406100  -  2635 1 0x300041792c0 3 syscall_end rval1: 0 rval2: 134217728 errno: 0 brk 0.001800 No error
95.407300  -  2635 1 0x300041792c0 3 syscall_start sysnum: 17 brk
95.415700  -  2635 1 0x300041792c0 3 syscall_end rval1: 0 rval2: 134217728 errno: 0 brk 0.008400 No error
95.417700  -  2635 1 0x300041792c0 3 thread_state state: 4 asleep in user data fault
95.419500  -  2635 1 0x300041792c0 3 address_fault address: 0x28000 fault_type: 0 access: 1
95.421600  -  2635 1 0x300041792c0 3 anon_zero address: 0x28000
95.440600  -  2635 1 0x300041792c0 3 thread_state state: 0 in userland
95.453200  -  2635 1 0x300041792c0 3 syscall_start sysnum: 98 sigaction
95.454800  -  2635 1 0x300041792c0 3 syscall_end rval1: 0 rval2: 0 errno: 0 sigaction 0.001600 No error
95.460900  -  2635 1 0x300041792c0 3 syscall_start sysnum: 3 read
95.483700  -  2635 1 0x300041792c0 3 strategy device: 118,22  block: 2262752 size: 0x200 buf: 0x60008105278 flags: 0x2200061
95.522200  -  2635 1 0x300041792c0 3 thread_block reason: 0x60008105338 stack: <tnf_symbols>
95.523200  -  2635 1 0x300041792c0 3 thread_state state: 7 asleep for other reason
95.523400  -  2635 1 0x300041792c0 3 thread_state tid: 0x2a10001fcc0 state: 1 in syscall/pagefault
95.939700  -  2635 1 0x300041792c0 17 syscall_end rval1: 512 rval2: 8193 errno: 0 read 0.478800 No error
95.972400  -  2635 1 0x300041792c0 17 syscall_start sysnum: 4 write
96.070000  -  2635 1 0x300041792c0 17 syscall_end rval1: 512 rval2: 8962 errno: 0 write 0.097600 No error
96.072000  -  2635 1 0x300041792c0 17 syscall_start sysnum: 3 read
96.078800  -  2635 1 0x300041792c0 17 strategy device: 118,22  block: 2262753 size: 0x200 buf: 0x60008105278 flags: 0x2200061
96.105100  -  2635 1 0x300041792c0 17 thread_block reason: 0x60008105338 stack: <tnf_symbols>
96.106100  -  2635 1 0x300041792c0 17 thread_state state: 7 asleep for other reason
96.106300  -  2635 1 0x300041792c0 17 thread_state tid: 0x2a1005d1cc0 state: 1 in syscall/pagefault

Interesting we appear to be blocking for a reason….ahhh following from a quick chat with John Alderson and reading his blog entry this now becomes clear.

Basically directio is still persistant on the file after Oracle is shutdown. DIRECTIO_ON allows you to force directio per-file and is used potentially by databases if their app tunable is so set (which in our case it is). The flag is set in the inode’s i_flag and hangs around cached within the inode in the DNLC and will effect files until the inode is flushed from the DNLC.

Ah, Oxford where some of the clever people go to college and enjoy the year long tradition of healthy competition on boats with Cambridge. However that wasn’t the idea, as this weekend Pheebs and I were going to meet some of her Univercity friends for a healthy dose of pub crawling and some Oxford punting. However what they don’t tell you is although punting is very enjoyable it’s quite hard work when your the poor sod with the punt. Originally, the flat-bottomed craft were used for moving heavy cargo but pleasure seekers quickly moved in on the scene however now a days people use them as a cheap and effective method of pub crawling….

What is punting?

Punting is the term used to describe the art of cruising along in a flat-bottomed boat. A person will stand at the back with a long pole which they grip with both hands, lower into the water and push on the bottom of the river bed, before pulling it back out. The pole can also be used to steer the boat. The punter lowers part of it into the water, then pulls it to the right to steer right, and left to steer left.

What is pub crawling?

The art of travelling from pub to pub drinking copious amounts of beer without falling over and whilst still maintaining an interesting and intellectual conversation with your fellow drinkers or anybody that will talk to you.

Still punting around made me thirsty so I had to recover with several beers…

If I ever get some pictures I’ll post them here!

Yep, time to bake a cake and not waste the 4 bananas I had left after camping with the boys last weekend. For this partitular version I used the following ingredients:

4 bananas, squished.
3 beaten and battered eggs
6 oz sugar
8 oz plain flour
1 teaspoon soda bicarbonate
1 teaspoon salt
4 oz melted butter

Butter the cake tin (using the butter wrapper!) and then lob the bananas into a blending machine to really squish them! For those of you who prefer larger lumps of banana then don’t squish so much! Add, the eggs, sugar and butter in the blending machine until you get a nice paste. In another bowel sift the flour, bicarbonate of soda and salt together. Add the banana paste together and mix well using a spoon (or hands if you like……no really!). Pour into the cake tin. If using the round ring cake mould, bake for 40 minutes at 180C. I used a loaf pan which cook about 50 minutes at 180C. Test the middle of the cake to check if it’s cooked before removing from the oven……

….eat when cold with a nice cup of tea!

Ah, we rocked on last night adding another couple of numbers to our ever growing covers set. Half way through the practice we had a couple of visitors to watch us perform in the face of Matt and Phoebe who were gently surprised at us. I guess all Phoebe has seen is me practicing so it was nice to finally see some work put to use! I guess we need to find a good place to gig now…..mmmm, I wonder where that’s gonna be! Kev managed to record the set so for your viewing pleasure you can grab them from here along with some divx recordings from Matt’s camera.