A day in the life of an Oracle DBA

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.

– Bobby