I thought I would do a fun “day in the life” blog post about the work I’m doing today. And then chaos ensues!
8:22 AM MST After starting this blog post and reading my email I updated my time card for yesterday. Pretty easy so far. Then I get a chat message that an important web site is down. One web server is flooding our database with locks – select for update. Fun! Web server is brought down and problem solved.
8:48 AM MST Checked on import as part of PeopleSoft financials dev database refresh from prod. First import failed part way. Second one is running but I had to let it fail on IMP-00015 object already exists errors to get to the point it was out after a day of importing. Normally it take about six days to do this import! Hopefully we can get this into Delphix at some point if we can get our network throughput straightened out and funding for the disk space.
9:01 AM MST Reviewed weekend PeopleSoft changes. 11 small migrations. Already prepped 6 on Friday. Have all week to prep the rest. Probably will do today if I don’t get interrupted.
9:18 AM MST Review possible technical architect projects – evaluate RAC, study OBIEE performance, improve DW batch job performance. Hmm. There are only so many hours in the day, but some of these seem interesting. I’m really pondering OBIEE and adhoc queries performance. But, it may be that the performance of the batch jobs on the weekend is more important to the business. That’s not as cool but it is something I can actually do something about. Batch jobs are great because I can change the SQL, break it up, add hints, etc.
9:46 AM MST One PS change prepped. Four to go. Whoo hoo!
9:59 AM MST Take survey on migration to Windows 7. My new laptop is sweet but there were a couple of issues that I documented.
10:24 AM MST Meeting about weekend changes. Bunch of things going in. May be another PeopleSoft change coming my way.
10:32 AM MST Both daughters (12 and 16 years old) are up. They are home from school. Evidently my 16 year old doesn’t know how to use the washing machine so I start a load for her. I telecommute two days a week and normally the critters are in school but this week is fall break for Chandler schools.
11:01 AM MST Started long running audit query on a database. This is more of a developer function but I’m verifying row counts. I guess being a PeopleSoft DBA you get called in to do some audit functions even though I’m not that familiar with the data. Made myself a nice salami sandwich while waiting for the first query to return.
11:53 AM MST Chaos ensues again. Email and chat messages interrupt the two things I’m already doing. My stack gets to about four items. Finally I’m back to prepping for another PeopleSoft change for the weekend. Only three more left to prep unless one gets approved late. Also, my first audit query completed nicely and the second ran fine in test so its going now in prod. Also, finished my lunch with two apples – one green, one red.
12:28 PM MST Little break – moved the laundry to the dryer, took out the trash, did some reading.
12:47 PM MST Coordinating some downtime on our Delphix environments while working on the next PS change. Evidently there is something about HP-UX’s virtual switch that is preventing us from getting good network throughput on our HP-UX VMs. Alas, it appears that all other Delphix customers with HP-UX are using physical servers so we are blazing a trail with the HP-UX VMs and Delphix.
1:16 PM MST Interrupted with issue with Payroll performance. The database was almost idle except for a normal export, but there were high i/o latencies. sar -d was reporting 43 millisecond reads on a certain device. Not sure if it was part of a database file system. Interesting note here is that from an AWR perspective db file sequential reads for the past hour were 8 milliseconds. This doesn’t seem bad but last Tuesday they were 3 milliseconds. We don’t use direct i/o on this database so the 8 milliseconds is an average of the reads cached in the unix filesystem cache and the actual disk i/o so the real i/o as reported in sar could be a lot more than 8 ms.
1:29 PM MST Did some more querying. I think the last hour was just less busy because we were at 2 ms the hour before. Here is my query for single block read wait times:
select sn.END_INTERVAL_TIME, trunc((after.time_waited_micro-before.time_waited_micro)/ (1000*(after.total_waits-before.total_waits))) "ave read milliseconds", (after.total_waits-before.total_waits) "number of reads", before.event_name from DBA_HIST_SYSTEM_EVENT before, DBA_HIST_SYSTEM_EVENT after, DBA_HIST_SNAPSHOT sn where before.event_name='db file sequential read' and after.event_name=before.event_name and after.snap_id=before.snap_id+1 and after.instance_number=1 and before.instance_number=after.instance_number and after.snap_id=sn.snap_id and after.instance_number=sn.instance_number order by after.snap_id;
Here is the output:
END_INTERVAL_TIME ave read milliseconds number of reads -------------------------- --------------------- --------------- 30-SEP-13 05.00.49.277 AM 7 2509 30-SEP-13 06.00.03.711 AM 3 25515 30-SEP-13 07.00.18.398 AM 3 281640 30-SEP-13 08.00.33.128 AM 2 293962 30-SEP-13 09.00.47.908 AM 3 334224 30-SEP-13 10.00.02.648 AM 5 503945 30-SEP-13 11.00.17.868 AM 4 608978 30-SEP-13 12.00.32.760 PM 3 892744 30-SEP-13 01.00.48.088 PM 0 1341677 30-SEP-13 02.00.02.882 PM 0 2467534 30-SEP-13 03.00.18.168 PM 0 2877788 30-SEP-13 04.00.33.095 PM 0 1582026 30-SEP-13 05.00.47.870 PM 1 801732 30-SEP-13 06.00.02.389 PM 0 574242 30-SEP-13 07.00.17.254 PM 3 12142 30-SEP-13 08.00.32.313 PM 0 110974 30-SEP-13 09.00.47.481 PM 1 67871 30-SEP-13 10.00.03.485 PM 1 137784 30-SEP-13 11.00.19.079 PM 1 180278 01-OCT-13 12.00.33.957 AM 3 326129 01-OCT-13 01.00.49.154 AM 5 551264 01-OCT-13 02.00.03.925 AM 5 560862 01-OCT-13 03.00.18.645 AM 1 513999 01-OCT-13 04.00.33.720 AM 4 19192 01-OCT-13 05.00.48.836 AM 8 5431 01-OCT-13 06.00.03.244 AM 9 3470 01-OCT-13 07.00.17.843 AM 4 256345 01-OCT-13 08.00.32.633 AM 2 667393 01-OCT-13 09.00.47.515 AM 5 263574 01-OCT-13 10.00.02.986 AM 2 583552 01-OCT-13 11.00.17.808 AM 4 1514417 01-OCT-13 12.00.33.205 PM 4 1282821 01-OCT-13 01.00.47.920 PM 3 412715 01-OCT-13 02.00.02.482 PM 8 317958 01-OCT-13 03.00.17.964 PM 7 560480
4 milliseconds isn’t bad but with unix level caching it sometimes is under 1.
1:50 PM MST – Coffee break. Black since I’m on a diet.
2:12 PM MST – Finished prepping for one more weekend change. Two more to go.
2:24 PM MST – Payroll issue revisited. Confirm process is 20 minutes longer than normal. Did awr report, checked plan of top query, it hasn’t changed. Is averaging 34 milliseconds per execution today which is the same as earlier days.
select ss.sql_id, 2 ss.plan_hash_value, 3 sn.END_INTERVAL_TIME, 4 ss.executions_delta, 5 ELAPSED_TIME_DELTA/(executions_delta*1000) "Elapsed Average ms", 6 CPU_TIME_DELTA/(executions_delta*1000) "CPU Average ms", 7 IOWAIT_DELTA/(executions_delta*1000) "IO Average ms", 8 CLWAIT_DELTA/(executions_delta*1000) "Cluster Average ms", 9 APWAIT_DELTA/(executions_delta*1000) "Application Average ms", 10 CCWAIT_DELTA/(executions_delta*1000) "Concurrency Average ms", 11 BUFFER_GETS_DELTA/executions_delta "Average buffer gets", 12 DISK_READS_DELTA/executions_delta "Average disk reads", 13 ROWS_PROCESSED_DELTA/executions_delta "Average rows processed" 14 from DBA_HIST_SQLSTAT ss,DBA_HIST_SNAPSHOT sn 15 where ss.sql_id = '3d56qsnvv3shc' 16 and ss.snap_id=sn.snap_id 17 and executions_delta > 0 18 and ss.INSTANCE_NUMBER=sn.INSTANCE_NUMBER 19 order by ss.snap_id,ss.sql_id; SQL_ID PLAN_HASH_VALUE END_INTERVAL_TIME EXECUTI Average ms ------------- --------------- ------------------- ------- ---------- 3d56qsnvv3shc 1288646537 20-AUG-13 05.00 PM 22091 14 3d56qsnvv3shc 1288646537 20-AUG-13 06.00 PM 3374 11 3d56qsnvv3shc 1288646537 27-AUG-13 02.00 PM 10666 39 3d56qsnvv3shc 1288646537 03-SEP-13 04.00 PM 21203 14 3d56qsnvv3shc 1288646537 10-SEP-13 11.00 AM 9254 39 3d56qsnvv3shc 1288646537 10-SEP-13 12.00 PM 1820 32 3d56qsnvv3shc 1288646537 17-SEP-13 05.00 PM 314 27 3d56qsnvv3shc 1288646537 17-SEP-13 06.00 PM 25256 15 3d56qsnvv3shc 1288646537 24-SEP-13 02.00 PM 10885 18 3d56qsnvv3shc 1288646537 01-OCT-13 04.00 PM 14446 34
I hacked the output to fit on the page. Varies a bit due to caching but same plan.
3:15 PM MST Ran into a snag prepping my next to last PS change. We don’t migrate menus and permission lists in a project. Have to see if we can push this one out. Yuck!
3:27 PM MST Schedule oil change and service for our van. We may be driving some teenagers up into the mountains this weekend.
3:36 PM MST Chat about dropping a partition from a table and local index.
3:57 PM MST Splitting headache. Maybe documenting every minute on the blog isn’t a good idea. Didn’t take much of a break for lunch. Time for some Earl Grey tea and brief relaxation.
4:22 PM MST Prepped for last change – simple SQL update. Built backup script to use CTAS to backup 7 rows each from two tables. Staged on production. Also, requested change with policy violation to be pushed out. Done with production preparation for now.
4:34 PM MST Finished up editing this blog post. I’ll do some more stuff after now until 5 pm but I wanted to finish the blog post today. Maybe this gives you an idea of my work life. Some cool performance stuff. Some mundane migration stuff. Reminds me of the way a flight instructor described his job – hours of boredom punctuated by moments of stark terror! In my case I’m not really bored with the mundane, but it is punctuated by the interesting, and occasionally interrupted by the stressful. Not quite stark terror since it isn’t really life threatening.
The life of a DBA – at least for one day.