C H A P T E R  12

Monitoring Exadata Performance

By now you have learned about the key Exadata performance features and the related performance metrics. Let’s see how we can use these for everyday tasks. We will look at standard tools available for database-layer and cell performance monitoring, and how to interpret their output.

Oracle Database and the Exadata cells provide a huge variety of different metrics, but before monitoring any metrics, you should ask yourself why you are monitoring them. Additionally, you should know what your action would be if a metric crosses some threshold. This leads to the follow-up question: which exact threshold should prompt some action from you—and why? In other words, you should know what are you trying to achieve (good response times for users) and how performance metrics relate to that.

The monitoring tasks covered here can be divided into the following categories:

• SQL statement response time monitoring
• Database layer utilization and efficiency monitoring
• Storage cell layer utilization and efficiency monitoring
• Advanced metrics and monitoring for Exadata performance troubleshooting

Note that we will focus on the Exadata-specific performance topics here and not the whole wide range of other Oracle performance topics, like lock contention or general SQL performance issues.

A Systematic Approach

Whatever metrics you monitor, you should have a purpose in mind. In other words, don’t collect and display metrics just because they are available; this will lead you nowhere or potentially even mislead you to fixing the wrong problem. Note that the term “performance” is vague—different people may mean different things when they use it. From an IT system user’s perspective, performance is ultimately only about one thing— response time. And not some response times of individual wait events measured at a low level; the end users don’t care about that. They do care about how much they have to wait for their business task to complete, like the time it takes from the report submission to actually seeing its output. This time is measured in regular wall-clock time; it’s as simple as that.

If your purpose in monitoring is to ensure good response times for your application users, then you should measure what matters—response time as your end-user experiences it. This would be the ideal entry point to performance monitoring. In addition to this entry point, you should measure more detailed lower-level metrics to break the end user response time down into individual components, like time spent in an application server and database time. Your application instrumentation and monitoring tools should keep track of which database sessions were used for which end-user task, so you can report what these exact database sessions were doing when a user experienced unacceptable response times.

When examining performance metrics because of an ongoing problem (of too long response times), you should start by identifying the sessions servicing this slow application or job and then drilling down into that response time. It would be more correct to call this performance troubleshooting, not just monitoring.

Note that there are other kinds of performance monitoring tasks, which you may want to do—for example, proactive utilization and efficiency monitoring. Performing these tasks allows you to keep an eye on the utilization headroom left in the servers and detect any anomalies and sudden spikes in system utilization and low-level response times, possibly even before users notice a response time difference. Yet another reason for collecting and monitoring performance and utilization data is for capacity planning—but capacity planning is outside the scope of this book. Also, because this is a database book, we won’t dive into any end-to-end performance measurement topics, which would involve identifying time spent in application servers, on the network, and so on.

We will start by looking at how to identify where a long-running query is spending most of its time. We’ll also look at how to tell whether a query is taking full advantage of Exadata’s performance features.

Monitoring SQL Statement Response Time

The best tool for monitoring long-running queries is Oracle 11g‘s SQL Real Time monitoring page. It is able to gather all the key performance information onto a single page, even in the case of parallel execution across multiple RAC instances.

The SQL Monitoring feature requires you to have a Diagnostics and Tuning Pack license. SQL Monitoring kicks in automatically if you run your query with parallel execution or when a serial query consumes more than 5 seconds of I/O and CPU time in total. Additionally, you can control the monitoring feature with MONITOR and NO_MONITOR hints. If you want to monitor your frequently executed short-running queries, the best tool for this would be to use ASH data and list the top wait events and top rowsources from there (using the SQL_PLAN_LINE columns in the V$ACTIVE_SESSION_HISTORY view).

If you are already aware of a performance problem (perhaps your users are already complaining of too long response times), then you should use a top-down approach for monitoring. You should identify the session(s) of the problematic users’ applications or reports and drill down into what these sessions are doing with ASH (which gives you the SQL_IDs of the top SQL statements for these sessions) and when needed, then drill down further into the top statements with SQL Monitoring reports.

Monitoring SQL Statements with Real-Time SQL Monitoring Reports

When you click the SQL Monitoring link in the Enterprise Manager performance page, you will see the latest monitored queries. The SQL Monitoring reports are present in Grid Control 11g R1 or 10g R5 (10.2.0.5). If you are not using Grid Control, then you can either use the built-in Enterprise Manager Database Console or run the SQL Monitoring reports manually from SQL*Plus as explained shortly. Note that the SQL Monitoring feature requires Diagnostics and Tuning Pack licenses.

Figure 12-1 shows the entry page to the SQL Monitoring reports. You can get there by clicking the SQL Monitoring link at the bottom of the Performance page in Grid Control. The SQL Monitoring page, as seen in Figure 12-1, lists the currently running, queued, and recently completed monitored SQL executions, with some key performance metrics and details, such as the degree of parallelism.

Figure 12-1. Enterprise Manager’s overview of Monitored SQL Executions

The Status column shows an icon with one of four statuses—running, done, error, or queued. When you click the status icon, you will be taken to the SQL statement’s detailed monitoring page. One of the most important pieces of information is the Duration column, showing how long a statement has been active. The duration is the wall-clock time from the start of the statement execution through the finish, or to the current time in the event the statement is still executing. Figure 12-2 illustrates the difference between duration (wall-clock) and CPU time in statement execution.

Figure 12-2. Statement Duration compared to Database Time in the SQL Monitoring page

The Duration column shows what users care about, which is the response time of a query since the SQL execution start. This is the time they have had to wait for the SQL to complete. Of course, the end users may have had to wait for much longer than the duration of the query, as the page in Figure 12-2 shows only the database response time. Time may have also been spent in the application layer or the network connection in between the user and the application server.

It is important to know that the duration measures time from SQL execution start all the way until the cursor is closed or cancelled (for example, when all data is fetched from it). This means that if your database can process the query in 30 seconds, but then millions of rows are fetched a few at a time, your query will take a long time as far as the application is concerned (thanks to the network ping-pong), but in fact only a little time is spent processing within the database. The Duration column still shows long query “runtime,” as the cursor is still kept open for fetching of the data. Remember, the duration measures time from when the cursor is executed all the way to when it is finally closed after all the fetches are done or the application has fetched enough.

This leads us to the next important metric—Database Time, seen in the sixth column in Figure 12-2. The Database Time metric shows the total time your query spent executing in the database. So, if you run a serial DML that runs for 60 seconds and spends all of the time executing inside the database, you will end up seeing 60 seconds of database time, too. However, if you are running some SELECT statement and are fetching a lot of rows, causing your session to spend (let’s say) 50% of its time executing in the database and another 50% waiting for the next fetch command (once it has sent an array of rows back to the application), you would see only half of that total 60-second duration as database time. In other words, you would see 30 seconds of database time, as the database session has been servicing your request only for 30 seconds and the rest of the time it was idle.

Looking at the second entry in Figure 12-2, you see that the duration of the query (the time from when the execution phase started) is 4.4 minutes, the query has executed in serial (the fifth column shows that), and it has consumed only 2.4 minutes of database time. So this indicates that the executing session has been doing something else for 2 minutes. It was either idle (probably waiting for the next fetch request) or executing some other statement (while the first statement’s cursor was still open).

The example we just discussed was about a single serial query. When you run a parallel query, you have multiple sessions executing pieces of the same query for you. Then the database time might end up being much higher than the duration (response time) of your query. If you look at the first entry in Figure 12-2, you see a statement with duration of 19 seconds, but the total time spent in the database is 9.5 minutes. When you look at the parallel column, you see that the session was executed with parallel degree 32, which means that you had multiple sessions actively working in the database for your query. All of these parallel sessions’ database time plus the query coordinator’s time is added into the Database Time column. This database time gives an idea of how much work was done in the database. But because the statement was parallelized, you don’t have to wait for that long. If you ran that same query in serial mode, then the database time would be in the ballpark of how much time you might have to wait. (Please take that last statement with a grain of salt, as in practice many other things may happen in SQL execution when switching from parallel execution to serial, so you might have some pleasant or unpleasant surprises in the response time).

Note that these entries in the SQL Monitoring overview page are not SQL statement-specific, but SQL statement execution-specific. So, if two user sessions were running the same statement, you would see two separate entries in this list. This allows you to examine exactly what the problem is with a specific user (who is complaining) as opposed to looking at statement-level aggregate metrics (like those V$SQL provides) and trying to figure out your user’s problem from there.

Real-Time Monitoring of Single Long-Running Query

Once you have identified your query of interest from the list of all long-running queries, you can click on its “running” icon in the left side of the list and you will be taken to the Monitored SQL Execution Details page shown in Figure 12-3. This page has a number of sub-tabs, so feel free to explore and see all the information that’s available there.

Figure 12-3. Monitored SQL statement execution details

The Monitored SQL Execution Details page has a lot of information in it. This page is pretty self-explanatory if you have read SQL execution plans before, so we won’t go through every single detail here, but will focus on the most important metrics. Compared to old-fashioned DBMS_XPLAN output, the SQL Monitoring page is very interactive, so make sure that you hover your mouse over and click on almost everything on the screen, to see the full array of functionality available to you.

Let’s start from the top section on the page. At the top of the screen, right after the Monitored SQL Execution Details header, you see a little icon, which shows the status of the selected SQL statement’s execution. The little circle will mean that the statement is still being executed (the cursor has not been closed nor cancelled).

The Overview section, illustrated in Figure 12-4, will show some basic details, like which SQL ID is being executed, by whom, and so on. You can see the SQL text when you click on the little (i) icon next to the SQL ID. You will see the SQL statement text and, beginning with version 11.2.0.2, you will also see the bind variable values used for the execution. Figure 12-5 shows the display that you get by clicking that (i) icon.

Figure 12-4. SQL Monitoring overivew section

Figure 12-5. Bind variable values in the SQL Monitoring detail page

Of course, whether you should use bind variables for your long-running reports and DW queries is an entirely separate question. You shouldn’t use binds for long-running queries in your DW; you’d want to sacrifice some response time for hard-parsing a new query plan for each combination of literal values and possibly get an optimal plan for each variable set. Nevertheless, monitoring bind variable values of an already running query is easy with Oracle 11.2.0.2 and later, because you no longer must resort to the ORADEBUG ERRORSTACK command.

The Time & Wait Statistics section in Figure 12-6 shows the familiar metrics of Duration and Database Time of a statement. Move your mouse over the different database time components to see how much time was spent waiting inside the database compared to running on CPU. The Wait Activity % bar shows the breakdown of wait events. Note that the 100% in this bar means 100% of the wait time component of database time, not of the entire database time (which also includes CPU time).

Figure 12-6. Time and Wait Statistics in the SQL Monitoring detail page

The IO Statistics section in Figure 12-7a shows some key I/O statistics for statement execution.

Figure 12-7a. I/O Statistics in the SQL Monitoring detail page

The Buffer Gets bar shows the total number of logical I/Os done in both the database layer and the cells (if Smart Scan kicked in). The IO Requests and IO Bytes statistics are self-explanatory, but note that those metrics show all I/O done for the given statement, which includes the Smart Scan I/O, any regular block I/O, and also TEMP tablespace I/O (done for sorting, hash joins, and for any other work area operations that didn’t fit into allowed PGA memory). Now you should begin to understand why the Cell Offload Efficiency is negative for the statement execution in the figure. This metric should ideally show the percentage of disk-to-database-host interconnect traffic that was avoided thanks to the Smart Scans performing filtering and projection early in the cells and returning only a subset of data. However, in a complex execution plan there is much more going on than just a Smart Scan against a single table. You have joins, aggregate operations, sorting, and direct path data loads, which all use extra I/O bandwidth, driving the offload efficiency percentage down. This is a good example of why focusing on only a single ratio is not a good idea. The single percentage value for offload efficiency hides a lot of information, such as where the percentage taken was from and the real values behind it. You can move your mouse over the percentage and see the underlying values used for the calculation.

So when moving your mouse over the ratio (see Figure 12-7b), you’ll see that the cells did read 486GB from disks, but much more data (715GB) was actually sent back and forth over the interconnect. The metric explanations in Figure 12-7b are actually incorrect. The Bytes Read From Disks actually means total bytes of reads and writes that Oracle Database has issued, not just for Smart Scans, but for any reason. And the Bytes Returned From Exadata actually means the total interconnect traffic between the database and the cells, caused by any reason, such as block reads and writes and arrays of returned rows by Smart Scans.

Figure 12-7b. Cell Offload Efficiency ratio in the SQL Monitoring detail page

If you are wondering why the I/O interconnect bytes is 715GB when the actual database-issued I/O is only 486GB, the explanation is in how these metrics are measured. The database I/O metric (the Bytes Read From Disk in Figure 12-6) is measured by the database layer, while the I/O interconnect bytes is measured by the low-level interconnect/Oracle networking layer. And one of the layers in between is the ASM layer, which manages the software mirroring, among other things. So the interconnect I/O traffic in this case is higher than the database traffic thanks to the write operations done by the SQL statement, which had to be mirrored by the ASM layer. So every MB written by database (whether because of direct path load or some work area operation spilling to temporary tablespace) resulted in the writing of 2MB of data thanks to ASM normal redundancy mirroring.

There are other reasons why the interconnect traffic may be higher than the actual amount of data read. One example is HCC compressed tables. If you have compressed your 10GB partition down to 1GB, then you will have to do 1GB worth of I/O to read it. But now if the Smart Scan uncompresses this data in the cells on the fly and returns all that 10GB of uncompressed data back over the interconnect (assuming no projection or filtration in the cell was done), the I/O interconnect bytes will be much higher than the amount of data read from disks. This would drive the Cell Offload Efficiency down to 10% for this example Smart Scan. All this is yet another reason why you shouldn’t focus solely on improving just the Cell Offload Efficiency ratio, but should rather look into where response time is spent instead. Time is what end users care about.

Execution Plan Rowsource Details

Now that you have checked the key metrics of your statement execution— duration, database time, parallelism used and how much of the database time is spent running on CPU vs. waiting— it’s time to drill down into the details of the execution plan at the row-source level. These are shown in Figure 12-8.

Figure 12-8. Execution plan rowsource activity monitoring in the SQL Monitoring detail page

Let’s focus on the right-hand columns of the execution plan output first. The CPU Activity column shows a breakdown of total CPU usage by the statement so far. The longest bar at the SORT ORDER BY line in the execution plan shows that this rowsource consumed 43% of total CPU usage of that statement execution so far. Note that this is 43% of total CPU consumption, not of total duration or database time of the statement execution. You should examine the Time and Wait Statistics section (shown earlier, in Figure 12-4) to see how much of the total database time was consumed by CPU usage and how much by waits.

The Wait Activity column shows a breakdown of which wait events this statement execution waited for. Again, the SORT ORDER BY rowsource has experienced the most waits, 72% of total wait time of that statement execution. Note that this bar consists of two different color bars. If you move your mouse pointer over these bars, you’ll see the names of these wait events. In this case these waits were direct path read temp and direct path write temp events, which you see with multi-pass work area operations such as sorts and hash joins. This column also shows percentages of total wait time of this statement execution, not the percentage of total runtime duration, nor total database time.

The IO Bytes column shows how many I/O operations or bytes were read or written by a rowsource. You can right-click on the chart to toggle the display of bytes or I/O operations. In Figure 12-8 you see that the SORT ORDER BY rowsource has done a total of 241GB worth of I/O. When you move your mouse over the different color bars, you’ll see the details about how much was written and how much was read (roughly 50/50, as the chart seems to show). The execution plan step LOAD AS SELECT above it has written about 125GB of data to disk. Note that this 125GB of data is measured at the Oracle database level, but the lower-level ASM layer will likely mirror (or triple-mirror, depending on your configuration) these writes, so actually twice as many bytes were written physically to disks. You can check the Cell Physical IO Interconnect Bytes session statistic to see how much data was really sent (and received) over the InfiniBand network; this metric is aware of the ASM mirror write overhead and any other low-level traffic too.

Let’s look at a few more columns of the Real Time SQL Monitoring page. The Timeline column you see in Figure 12-9 is one of the most important columns for understanding where the SQL statement spends its time.

Figure 12-9. Row-source activity timeline in the SQL Monitoring detail page

The Timeline column in the figure shows a visual timeline of individual execution plan rowsources’ activity. It is based on ASH samples; ASH collects SQL execution plan line-level details starting from Oracle 11gR1. Look into the brackets in the Timeline column header. This should show you the total runtime duration of this SQL execution, 2226 seconds in this case (around 37 minutes). So the total width of the timeline column means about 37 minutes of wall-clock runtime. Now it’s easy to visually interpret the length and position of these bars in each rowsource in the execution plan. When you look at the TABLE ACCESS (FULL) T4 rowsource at the bottom of the plan, you see that this table scan was active from the beginning of the execution and continued up to around two-thirds of the total Timeline (to around 1400 seconds) and then it completed. So it looks like this table scan was active during most of the execution time.

Oracle execution plans are trees of rowsource functions with strict hierarchy enforced, so a child rowsource can pass its results only to its direct parent. In our case, the TABLE ACCESS FULL against T4 fetched some rows and passed them back to its parent operation, PX BLOCK ITERATOR, which then sent the rows back to the PX SEND RANGE operator, which knows how to send results to other slaves via the PX Table Queue buffers in the SGA. Another set of slaves received these rows using the PX RECEIVE rowsource and passed these rows to their parent, the SORT ORDER BY rowsource, which performed the sorting of these rows. Then the SORT ORDER BY rowsource just repeated its loop and asked for more rows from its child operator PX RECEIVE, which then read (consumed) the table queue buffers for more rows put there by the first set of slaves (producers). We are not going deeper into SQL execution engine internals here, but hopefully this example has illustrated the hierarchical nature of the SQL execution and how the data “flows” upward through the execution plan tree toward the root of the tree (CREATE TABLE STATEMENT in this case).

When you look at the timeline bars, you see that all the bars starting from PX RECEIVE and below it started roughly at the same time and ended roughly at the same time, too. We say roughly, because this data comes from ASH samples, sampled once per second only, so we don’t have microsecond accuracy here. And we don’t need it anyway, as our query runs for much longer than a second. But anyway, the timeline bars indicate that the table scanning part of the query, including these “data transportation” steps for that data (PX RECEIVE, PX SEND RANGE, and PX BLOCK ITERATOR) took around 66% of the total query response time. If we want to make our query faster, we should probably focus on that part. we should either scan less data, filter more (in cells hopefully), access less partitions or just increase the scanning throughput (by increasing parallelism in this case, because this TABLE ACCESS rowsource wasn’t waiting too much for I/O, as shown in Figure 12-8, it’s not I/O-bound yet and the database nodes had plenty of CPU resource left).

When you look at the upper rowsources (LOAD AS SELECT and higher), you see that they have only been reported active in the last third of the query response time, extending all the way to the end of execution. So, if we somehow made only this data loading part faster, we would only win up to 33% of the response time back, even if we could make the loading part infinitely fast. The table access and sorting would still take the majority of the response time. The timeline bars are very valuable for quickly understanding in which execution plan tree part (branch) most of the response time is spent.

The timeline bars are just the first thing to check. There are lots of other useful details in the SQL Monitoring report, too. For example, if you look at the SORT ORDER BY line in Figure 12-9, you see that the sort operation has been active throughout the whole execution of this statement. And if you know the basics of sorting, it should make sense—the sorting rowsource was active for the first two-thirds of the time because it was fetching data into sort buffers and sorting it (and spilling some data to temporary tablespace). After the sort itself was complete (the child rowsource returned an “end of data” condition), the sorting rowsource function had still had to be invoked. It is by invoking that function that the sort operation returns the sorted rows to its parent operation. This is why the parent rowsources became active only toward the end of the execution timeline—because all the rows had to be fetched and sorted first, before anything could have been returned for further processing. And once all the rows were fetched and sorted, there was no reason for the SORT ORDER BY rowsource to visit its child rowsources again. This is why the timeline bar for TABLE ACCESS ended at around two-thirds of the total execution duration timeline.

Manually Querying Real-Time SQL Monitoring Data

All the pretty charts in Grid Control are based on some V$ or DBA_ views internally, so if you don’t happen to have access to Grid Control or Enterprise Manager Database Console (or it is just broken), you can get what you want from the V$ views directly. You probably don’t have to access the V$ views for your everyday monitoring and tuning tasks, but nevertheless it’s useful to know where this information comes from, as it may become handy for custom monitoring and advanced problem troubleshooting. Following are some key views to be aware of:

• The GV$SQL_MONITOR view contains the statement execution-level monitoring data. When multiple sessions are running the same statement, you will have multiple entries in this view. So, make sure that you query the right execution, by using the right search filters. For example, you should pay attention to which SID and INST_ID you are really looking for (or PX_QCSID, PX_QCINST_ID if monitoring a parallel query) and whether the STATUS column still shows EXECUTING if you are trying to troubleshoot a currently running query.
• The GV$SQL_PLAN_MONITOR view contains execution plan line-level metrics, monitored and updated in real time. For example you can query the IO_INTERCONNECT_BYTES and compare it to PHYSICAL_READ_BYTES and PHYSICAL_WRITE_BYTES to determine the offloading efficiency by each individual execution plan line, instead of the whole query efficiency. Note that increasing the offloading efficiency percentage should not be your primary goal of monitoring and tuning – where you spend your response time, matters.
• The GV$ACTIVE_SESSION_HISTORY view contains columns like SQL_PLAN_LINE_ID, SQL_PLAN_OPERATION and SQL_PLAN_OPTIONS starting from Oracle 11gR1. You can query these columns, in addition to SQL_ID, to find the top rowsources of an SQL execution plan, too, instead of just listing the top SQL statement.

Reporting Real-Time SQL Monitoring Data with DBMS_SQLTUNE

If you do not have access to Grid Control or Enterprise Manager Database Console for some reason, you can also extract the SQL monitoring details using the DBMS_SQLTUNE.REPORT_SQL_MONITOR package function. You can use the following syntax, but make sure you read the related documentation to see the full power of this feature. Note that the text below is edited, as this function generates very wide output, which wouldn’t fit the book pages.

DBMS_SQLTUNE.REPORT_SQL_MONITOR can also take HTML as a value for the TYPE parameter, instead of TEXT, in which case the output is generated as HTML. If you spool this output into an HTML file and open it in the browser, you will see much nicer output than just text. And starting with Oracle 11.2, you can also use ACTIVE as a parameter and spool that output into an HTML file. Now if you open this file in the browser, you will see the SQL Monitoring page almost exactly as it looks in the Grid Control! And all the data required for displaying that report is self-contained in the spooled HTML file —no database access needed when opening it! So this is very useful if you want to send a detailed self-contained report with some SQL execution problem to someone over the email.

Controlling SQL Monitoring

SQL Monitoring kicks in immediately for all statements executed with parallel execution, no matter how long they run. For serially executed statements, the SQL Monitoring does not kick in immediately, as it’s not designed to monitor typical fast OLTP queries, which are executed many times per second. Nevertheless, if a serial query has consumed more than 5 seconds of total CPU and/or I/O wait time, it’s considered as a long-running query and the SQL Monitoring is enabled for that statement execution. This happens seamlessly on-the-fly, and statement restart is not needed.

You can also use MONITOR and NO_MONITOR hints to control the SQL monitoring for a statement. V$SQL_HINT shows all the hints available for use and the version when they were introduced. For example:

Note that the NO_MONITORING hint is something completely different despite the similar name. The NO_MONITORING hint allows you to disable the predicate usage monitoring on table columns (sys.col_usage$), and it has nothing to do with the Real-Time SQL Monitoring option introduced in Oracle 11g.

Monitoring SQL Statements using V$SQL and V$SQLSTATS

The performance monitoring in the “olddays” before-Oracle 10g ASH was usually done using various V$ views, which showed aggregated instance-wide metrics. For example, the Statspack’s TOP-5 wait events report section was just a delta between two V$SYSTEM_EVENT view snapshots. The TOP SQL reports were based on V$SQL snapshots, which externalize the execution statistics and resource consumption for each child cursor still in library cache. However, in a large database system (think e-Business Suite or SAP), you can have tens of thousands of cursors in the library cache, so gathering and storing deltas of all of their stats is not feasible. That’s why tools like Statspack and AWR store deltas of only some top resource-consuming statements and ignore the insignificant ones. Remember that as these tools gather instance-wide data, they may end up ignoring a long-running statement if there are only a few sessions executing it. A single session running a bad SQL statement may not be “heard” in the noise of all the other sessions in the instance—potentially thousands of them. This instance-wide scope performance data analysis is not as powerful as the session-level ASH data slicing and dicing. With ASH you can drill down into any single session, regardless of how many sessions in total you have making noise in the instance.

If you use Exadata, you must be running at least Oracle 11g R1 on it, so all these superior tools are available, assuming that you have the Diagnostics and Tuning Pack licenses for your Exadata cluster. By the way, we haven’t seen an Exadata-using customer without Diagnostics and Tuning Pack licenses yet, so it looks like the vast majority of Exadata users do not have to resort to old tools like Statspack or create a custom ASH-style repository themselves (although it’s easily doable with a few lines of PL/SQL code polling V$SESSION or its underlying X$KSUSE view in each instance).

The V$SQL and V$SQLSTATS views still do have some advantage over SQL Monitoring and ASH-style sampled data in a few cases. For example, if you want to measure metrics like the number of executions, buffer gets, parse calls, fetches, or rows returned by the SQL child cursor, you can get this data from both Real-time SQL Monitoring (V$SQL_MONITOR) or the V$SQL/V$SQLSTATS views, but not ASH. But the problem with SQL Monitoring is that it doesn’t monitor short-running queries at all, therefore making it unusable for keeping track of OLTP-style small queries executed many times per second. Even adding a MONITOR hint into every query of your application would not help, as the maximum number of monitored plans is limited (controlled by the _sqlmon_max_plan parameter, which defaults to 20 plans per CPU) and you would likely end up with real-time plan statistics latch contention as well. The SQL Monitoring feature is not meant to monitor short-running queries executed many times per second.

And this leaves us with V$SQL and V$SQLSTATS. They both maintain similar data, but they are internally different. Whenever you query V$SQL without specifying an exact SQL_ID, Oracle has to traverse through every single library cache hash bucket, and all cursors under it. This may contribute to library cache mutex contention if you have a busy database and lots of cursors in the library cache, because when you traverse the library cache structure and read its objects’ contents, you’ll have to hold a mutex on the object. Note that starting from Oracle 11g, all library cache latches are gone and are replaced by mutexes. These same mutexes are used for parsing, looking up, and pinning cursors for execution, so if your monitoring queries poll V$SQL frequently, they may end up causing waits for other sessions.

The V$SQLSTATS view, which was introduced in Oracle 10gR2, doesn’t have this problem. Starting from Oracle 10gR2, Oracle actually maintains SQL execution statistics in two places— inside the child cursors themselves (V$SQL) and in a separate cursor statistics array stored in a different location in the shared pool. This separation gives the benefit that even if a cursor is flushed out from the shared pool, its stats in this separate array may remain available for longer. Also, when monitoring tools query V$SQLSTATS, they don’t have to scan through the entire library cache, thanks to the separate array where stats are stored. This means that your monitoring tools won’t cause additional library cache latch (or mutex) contention when they use V$SQLSTATS instead of V$SQL. Both Statspack and AWR do use V$SQLSTATS to collect data for their top SQL reports.

Let’s look into V$SQLSTATS (the V$SQL view has pretty much the same columns, by the way). Some of the output here is removed to save space:

The highlighted rows starting, with IO_CELL, are metrics related to Exadata storage cells (although the IO_INTERCONNECT_BYTES is populated on non-Exadata databases as well, thanks to a bug). You would want to compare these cell metrics to database metrics (like physical_read_bytes) to understand whether this SQL statement is benefitting from Exadata Smart Scan offloading. Note that these metrics, which merely count bytes, should not be used as the primary metric of performance ; again, the primary metric, the starting point, should always be response time, which you can then break down into individual wait events or into execution plan rowsource activity (with the SQL Monitoring report or ASH). You can learn more about the meaning of the metrics shown here in Chapter 11.

Note that even though the V$SQLSTATS view also contains the PLAN_HASH_VALUE column, it actually does not store separate stats for the same SQL ID with different plan hash values. It aggregates all the stats generated by different plans of the same SQL ID under a single bucket. So you don’t really know which plan version consumed the most resources from this view. Luckily in Oracle 11.2 there is a new view, named V$SQLSTATS_PLAN_HASH, which you should query instead. It organizes and reports the stats broken down by SQL ID and plan hash value instead of just SQL ID as V$SQLSTATS does.

Monitoring the Storage Cell Layer

Let’s look at how to monitor the storage cell layer for utilization and efficiency. As you already know, the storage cells are regular commodity servers with some disks attached to them and running Linux. You can use regular Linux OS monitoring commands and tools to keep an eye on OS metrics like CPU usage or disk I/O activity. The only catch is that Oracle does not allow you to install any additional (monitoring) daemons and software on the cells— if you still want to have a supported configuration.

The good news is that Oracle cell server software and additional OS Watcher scripts do a good job of collecting detailed performance metrics in each cell. The following sections show how to extract, display, and use some of these metrics.

Accessing Cell Metrics in the Cell Layer Using CellCLI

The cell-collected metrics can be accessed using the CellCLI utility. That’s in fact how the Exadata storage cell plug-in for Grid Control retrieves its data. You have seen CellCLI used in earlier chapters. Following are a few examples of using CellCLI for retrieving performance metrics. The command names should be fairly self-explanatory - we will cover the CellCLI commands in more detail in Appendix A.

Accessing Cell Metrics Using the Grid Control Exadata Storage Server Plug-In

If you have configured the System Monitoring plug-in for Exadata Storage Server, you will be able to see some cell-level metrics, reports, and charts in Grid Control. The plug-in installation is out of the scope of this book, but it’s well documented in the plug-in’s installation guide.

Currently the Exadata Storage Server monitoring plug-in gives only some basic metrics to monitor and is not very sophisticated for systematic cell performance troubleshooting or monitoring. Nevertheless, it will give you a more convenient way for monitoring cell statistics changing over time, compared to running CellCLI’s list metrichistory commands manually. When you initially navigate to a storage cell target (or group of cells) in Grid Control, you may not see any charts defined there yet. In Figure 12-10, we have created a group called “cells” from the Exadata Storage Server targets and navigated to the Edit Group page. This is where you can add new charts for collected cell-level metrics.

Figure 12-10. Adding storage cell metrics into Grid Control monitoring charts

All the chart definitions in Figure 12-10 have been manually added for the cell group. You can add charts yourself, by clicking the Add button, which will bring you to the Add Chart page shown in Figure 12-11.

Figure 12-11. Selecting a “highest-average” chart for monitoring cells with highest read I/O requests

To see the cell metrics available, you’ll have to select Oracle Exadata Storage Server as the chart type and pick one of the metrics to show. You probably want to use the Group Statistics for monitoring the whole cell group as a starting point, instead of monitoring all 14 storage cells (in a full rack) separately. The group statistics allow you to sum together stats from all the cells in the group (when monitoring total disk I/O throughput, for example) or show minimum, maximum, averages and standard deviation across all cells (when monitoring average disk I/O response times, for example). Pay attention to what the metric means and which aggregation operations make sense for a given metric. For example, it doesn’t make much sense to display the sum of all average disk I/O response times in a chart. The metrics starting with Avg show average values over multiple objects monitored. For example, the Avg Celldisk Reads (MB) monitors average megabytes read per celldisk. On the other hand, the Total Celldisk Reads (MB) metric sums together the MB read by all cell disks in a cell. And now if you use the Group Statistics option to monitor multiple cells, you should use Sum to see the total MB read from cell disks across all cells and Average or Min/Max to see the average per cell or a cell with the smallest or biggest MB read cell disk throughput.

If you do want to monitor individual cells— for example, the two storage cells with the worst offload efficiency—then you can either define a separate offloading efficiency chart for each cell (and end up with 14 charts in a full rack configuration) or you can select Targets With Lowest Average as the chart type, as shown in Figure 12-12.

Figure 12-12. Selecting a “lowest average” chart for monitoring cells with worst offload efficiency

You can read more about the meaning of various metrics in the Oracle document “Enterprise Manager System Monitoring Plug-In Metric Reference Manual for Oracle Exadata Storage Server.”

Now, you can reorder the charts on the cell group dashboard by clicking the Reorder button as shown in Figure 12-10 earlier. This will show you a list of defined charts, which you can then reorder on the screen, as seen in Figure 12-13.

Figure 12-13. Ordering the storage cell metric charts in Grid Control

Now you are ready to view your charts. Depending on how many of them you configured, you should see a screen layout like that in Figure 12-14.

Figure 12-14. Multiple cell-level metrics displayed in Grid Control

Note that when you first configure the charts, they will be empty. If you wait for a few minutes, you should see the first data points appearing, and after a day has passed, the charts should be fully populated (if Last 24 Hours is selected in the View Data drop-down). You can click Customize Charts to modify the chart metrics again.

Now let’s look at some of the individual metrics we have put onto the page, as shown in Figure 12-15.

Figure 12-15. Various celldisk average metrics charts displayed in Grid Control

In the Avg Celldisk Small Read Latency (msec) chart here, we do see an issue. An hour before 12PM, the average small block I/O (under 256kB) latency has jumped up, probably because more large I/O operations were done in the cell. We can conclude this from the other two metrics in the top row; the Avg Cellidisk Read Requests has significantly dropped, while the Avg Celldisk Reads (MB) has remained the same, or actually even increased slightly. So there are more large I/Os being done, perhaps due to more queries using a Smart Scan. The small I/O latency has suffered because of this. Your OLTP database users running on the same cluster may notice that.

This is a place where you should find out what causes all this extra I/O. We will look at it later in this chapter. If you want to avoid situations where large Smart Scans impact small (single-block) IOs, you should consider enabling the I/O Resource Manager (IORM), which allows you to set the IORM goal to optimize random I/O latency as opposed to full scanning throughput. Additionally, you could make sure that your hot segments accessed with single-block reads are cached in flash cache. See Chapter 7 for more about IORM and resource management.

Figure 12-16 shows an example of the total cell disk I/O throughput chart. Note that the metric used starts with “Total,” indicating that the throughput MB values are summed over all twelve disks in the cell (as opposed to the Average metrics, which show averages across the disks). This is a very important point. If you are summing together average metrics like in the Avg Celldisk Reads section (top right corner) of Figure 12-15, then you will still end up with a sum of the average cell disk read rates, not the total aggregate throughput of all disks in the cell. The cell disks’ average metrics are good for charting things like the min, max, and cell-level average I/O latencies or disk utilization figures, but not valid for monitoring things like I/O throughput of all cells.

It is valid to sum together Total Celldisk metrics to get the total aggregate throughput, so from Figure 12-16 we see that the aggregate disk read throughput across all the cells is around 2000MB/second for the given workload.

Figure 12-16. Celldisk-level Total metrics summed together for monitoring total I/O throughput

Sometimes, especially when the monitoring UI charts don’t seem to make sense, you might ask where these charts take their data from. This is easy to find out, as the Grid Control metrics plug-ins are just Perl scripts, which then run command-line utilities like CellCLI or plain SSH clients to fetch their metrics. You can check the directory where you have installed the Exadata Storage Cell Server monitoring plug-in yourself:

Let’s take a quick look at one of these Perl scripts, oracle_cell_celldisk_metrics.pl, to see where it gets its data:

As you can see, the Exadata Cell Grid Control plug-in is merely a bunch of Perl scripts, which then log into target cells via SSH and run regular CellCLI commands with XML output mode. The output is then parsed and returned to the Grid Control agent.

Now that we know which actual command the Grid Control plug-in uses for pulling data, we can run it ourselves and see which data it includes. Note that there’s an additional filter condition showing only one metric for brevity.

The grid disk names starting with FD_ indicate that these lines are reported for flash disks (each cell has 4 × 96GB flash cards, but each flash card presents four flash disks to the operating system, totaling 16 flash disks per cell). So, using this exercise we have found out whether the cell-disk metrics include flash disk metrics in addition to regular disk drives— and yes, they do. This makes some of the charts lie, as the flash read times that are an order of magnitude faster will make the average regular disk read times look better as well. In fact, some of the cell disks have a pretty bad small read I/O latency. For example, up to 30 milliseconds per request on average, which is much higher than the average seek + rotational + data transfer latency should be for a modern 15000 RPM disk, even if it is 100% busy with random I/O requests. This probably indicates I/O queueing somewhere, likely in the OS I/O queue, which you can confirm by looking at the await and svctm columns in iostat output (more about iostat later in this chapter, but man iostat is your friend).

So, ideally you should monitor the flash disks and good old spinning disk drives separately, by either post-processing the returned data or just running two separate CellCLI commands in your monitoring tools. CellCLI allows you to filter its results further using a regular expression, as shown here:

Now we see only the flash drives. You can read more about the CellCLI usage and syntax examples in Appendix A of this book and also in the official documentation, Oracle Exadata Storage Server Software User’s Guide.

Which Cell Metrics to Use?

Which cell metrics to use is an important question. Oracle provides a huge variety of different metrics, from the database level, the host server level, and the Exadata cell level. It is very easy to get lost in them or even worse, get misled and troubleshoot a wrong or non-existent problem. In performance troubleshooting, we should start from what matters—user response time—and drill down from there (as explained in the previous sections of this chapter). But general efficiency monitoring, utilization overview, and capacity planning are sometimes good reasons for examining cell-level aggregated metrics.

This may come as a surprise if you have expected more, but there is no long list of secret and special Exadata metrics you should monitor in your cells. A cell is just a server, with RAM, CPUs, and disks, sending data out over a network link. So the fundamental metrics you would want to monitor at the cell level are the same you’d use in any server: CPU utilization, system load, memory utilization and disk utilization, and I/O throughput and latency. The most important metrics are available in the Grid Control Storage Cell monitoring plug-in, and the rest can be extracted from OS Watcher logfiles. The advanced metrics come into play only when dealing with bugs or some rare, very specific performance issues, so they shouldn’t really be actively monitored unless there is a problem.

One topic deserves some elaboration— the CPU usage monitoring, both in the database and cells. The data warehouses and reporting systems, unlike OLTP databases, don’t usually require very quick response times for user queries. Of course, the faster a query completes, the better, but in a DW, people don’t really notice if a query ran in 35 seconds instead of 30 seconds. But a typical OLTP user would definitely notice if their 1-second query took 6 seconds occasionally. That’s one of the reasons why in OLTP servers you would not want to constantly run at 100% CPU utilization. You cannot do that and also maintain stable performance. In an OLTP system you must leave some headroom. In DW servers, however, the small fluctuations in performance would not be noticed, and you can afford to run at 100% of CPU utilization in order to get the most out of your investment.

However, Exadata complicates things. In addition to having multiple database nodes, you also have another whole layer of servers: the cells. Things get interesting especially when running Smart Scans with high parallelism against EHCC tables. That’s because offloaded decompression requires a lot of CPU cycles in the cells. Thus it is possible that for some workloads your cells’ CPUs will be 100% busy and unable to feed data back to the database layer fast enough. The database layer CPUs may be half idle, while cells could really use some extra CPU capacity.

The risk from cell utilization reaching 100% is the reason Oracle made cellsrv able to skip offload processing for some datablocks and pass these blocks straight back to the database (starting in cellsrv 11.2.2.3.0). The cell checks whether its CPU utilization is over 90% and whether the database CPU utilization (it’s sent in based on resource manager stats from the database) is lower than that. And if so, some blocks are not processed in the cells, but passed through to the database directly. The database then will decrypt (if needed) and decompress the blocks and perform projection and filtering in the database layer. This allows you to fully utilize all your CPU capacity in both layers of the Exadata cluster. However, this automatically means that if some blocks are suddenly processed in the database layer (instead of being offloaded to cells), then you may see unexpected CPU utilization spikes in the database layer, when cells are too busy. This shouldn’t be a problem on most DW systems, especially with properly configured resource manager, but you would want to watch out for this when running OLTP or other low-latency systems on Exadata.

As usual, Oracle provides good metrics about this pass-through feature. Whenever the offload processing is skipped for some blocks during a Smart Scan and these blocks are sent back to the database layer for processing, the statistic “cell physical IO bytes pushed back due to excessive CPU on cell” gets incremented in V$SESSTAT/V$SYSSTAT and AWR reports. Read more about this feature and statistic in Chapter 11.

Monitoring Exadata Storage Cell OS-level Metrics

Oracle Database and the cellsrv software do a good job of gathering various performance metrics, but there are still cases where you would want to use an OS tool instead. One of the reasons is that usually the V$ views in Oracle tell you what Oracle thinks it’s doing, but this may not necessarily be what’s really happening if you hit a bug or some other limitation of Oracle’s built-in instrumentation. One of the limitations is low-level I/O measurement.

Monitoring the Storage Cell Server’s I/O Metrics with iostat

Both Oracle Database and the storage cells do measure the I/O Completion Time; in other words, the response time of I/Os. With synchronous I/O operations, Oracle’s I/O wait time is merely the system call (like pread) completion time. With asynchronous I/O, the response time measurement is trickier, as an asynchronous I/O submit system call will not block and wait; it will return immediately in microseconds and some I/O reaping system call will be executed later, which will mark the I/O operation as complete. The Exadata storage cells keep track of each asynchronous I/O request (for example, when it was submitted) and once the I/O is successfully reaped, they will check the reaping timestamp against that I/O’s submit timestamp and know its duration.

Regardless of this extra cellsrv-level I/O monitoring, the cells still don’t break the I/O response time into the two important components: how much time this I/O request spent uselessly waiting in the OS I/O queue before it was even sent out to the SCSI device, and how long the actual hardware service time was once the I/O request was sent out to the hardware. Comparing the I/O service time to waiting time gives an important clue about whether the storage hardware itself responds slowly, in which case the service time is higher than you would expect from a modern disk drive.

Of course, there may be other overhead, like SAN storage network roundtrip times and any extra latency caused by storage controllers, switches, and so on. But remember, Exadata is not connected to SAN storage; the disks are attached directly to the storage cells. Each storage cell has a little LSI MegaRaid controller in it, and the disks are attached to that controller. There are no complex network components between the disks and storage cells, which might drive up latency or fail. More importantly, there are no “other” databases or applications connected to the storage, which you have no control over, but which could suddenly start saturating the disks without a warning. All you would see is that the disk I/O service times suddenly go up as the storage array gets overloaded.

Anyway, a small I/O request (up to 256 KB) against a modern 15000 RPM disk drive should ideally have average service time of 5–7 milliseconds per I/O request. This comes from a 3.5ms average seek latency, 2ms average rotational latency, plus 0.4ms for transferring the 256kB over SAS channels. In theory this average seek latency is a pessimistic figure, assuming that the whole disk is full and the disk read/write heads have to do random seeks across tracks from end to end of the disk cylinders. But you probably have configured your disks into hotter and colder regions (the RECO disk group, for example), and the colder regions are visited much less frequently, driving the real average seek times shorter. So, while you may get these low 2–3ms service times when your disk heads don’t have to seek too far, in practice, 10ms average I/O service times are completely OK once you run real production workloads.

The whole point of this explanation so far is really that it is possible to know what the ideal disk service times should be for Exadata cells disk drives, and if the service times are constantly much higher than that, then there is some problem with the storage hardware (disks or controllers). With SAN storage, high OS-level service times could also mean that there is some queuing going on inside the SAN network or the storage array (for example, if a thousand other servers are hammering the same storage array with I/O). But as said above, Exadata storage cells have dedicated storage in them; only the current cell OS can access this storage, and all IOs are visible in iostat.

So, what if the service time is OK, but Oracle (cellsrv) still sees bad I/O performance? Well this may mean there is still queuing going on inside the cell Linux servers—and iostat can show this information, too. You can have only a limited number of outstanding I/Os in the “on-the-fly” state against your storage controller LUNs. The storage controller needs to keep track of each outstanding I/O (for example, it has to remember where in the host RAM to write the block once it is read from disk and arrives at the controller), and these I/O slots are limited. So the Linux kernel does not allow sending out more I/Os than the storage controller can handle; otherwise a SCSI reset would occur. These throttled I/Os will have to wait in the OS disk device I/O queue— and they are uselessly waiting there; they aren’t even sent out to the storage controller yet. Only when some previously outstanding I/O operation completes will the first item in the queue be sent to the disks (assuming that the I/O latency deadline hasn’t been reached for some request; cellsrv uses the Linux “deadline” I/O scheduler).

If you do have I/O waiting (queueing time) going on, then the await (average I/O completion time) column in iostat will be significantly higher than the svctm (estimated I/O service time) column. Note that the name “await” is somewhat misleading, as it does not show only the wait (queuing) time, it shows the total wait plus service time. Similarly, the avgqu-sz column does not show just the average I/O wait queue length, but rather the average total number of not completed I/Os in the I/O request queue, regardless of whether they have already been sent out to storage hardware (are already being serviced) or still waiting in the I/O queue (not yet serviced).

Linux iostat shows statistics for the disk partition and the cell software RAID device (used for cell OS partition mirroring). We can filter out those lines so that only the physical disk stats would be listed. For example:

Wait a minute! Shouldn’t we see fewer disks, as each cell has only 12 hard drives in it? We see so many disks because in addition to the 12 hard disks, cells also have their flash cards presented as separate disks. Finally, there’s also one USB disk. You can use the lsscsi command in the cell to see all disks detected by the OS:

The LSI disks here are the hard disks presented to the host by the LSI SCSI RAID controller (from devices sda to sdl), the Unigen PSA4000 is the USB disk, and the MARVELL ATA disks are the flash cards. If you compare the average I/O service times (svctm) in iostat, you’ll see that the devices belonging to flash cards have a service time an order of magnitude lower than hard disk devices. So, if you want to monitor only the hard-disk devices, you can filter iostat output this way:

Advanced Cell Monitoring With OS Watcher

While the database-level wait profile and SQL Monitoring should be used as a starting point for performance monitoring and troubleshooting, sometimes these approaches are not enough and you want to drill deeper. This section explains one additional data source for that. Exadata storage cells come with a preinstalled tool called OS Watcher, located in the /opt/oracle.oswatcher/osw directory. This tool is just a set of shell scripts, which then run standard OS tools, like vmstat, iostat and netstat, to collect their data. OS Watcher’s benefit is that it runs at OS level, not inside a database, so it is not affected by database hangs and performance issues or cases where the database’s V$ views don’t show the truth or have enough detail. Additionally, the high-frequency OS Watcher collectors sample data every second or few seconds, allowing it to detect short “hiccups” or bursts of activity.

You can check whether the OS Watcher is running by simply searching for any processes with “OSW” in their name (be sure to search for both upper and lower case):

Apparently, the OS Watcher is running in this storage cell and there are a number of Exadata-specific collectors enabled, too. If you want to see the hierarchy of the OS Watcher process daemons, then on Linux you can use either the ps -H command shown in the first chapter or the pstree command as shown here:

The OS Watcher daemons store their collected data in the /opt/oracle.oswatcher/osw/archive/ directory. It doesn’t use any special format for storing the data; it just stores the text output of the standard OS tools it runs. This makes it easy to use regular text processing utilities, like grep, AWK or Perl/python scripts to extract and present the information you need. Here’s an example:

Each directory contains archive files with corresponding command output:

There is a separate bzipped file saved for each hour, making it easy to manually investigate past performance data or write a quick AWK, grep or Perl script, which extracts only the data of interest. The example below extracts iostat I/O statistics from a bzipped file from 9AM on May 25, 2011:

The OS Watcher output samples are prefixed by a timestamp line, which starts with “zzz” as you see above. This shows you the exact time, up to the second, when the OS command was executed and what the sample interval was. Note that this “zzz” line will only show you when the monitoring command was executed. Some commands are executed only once per hour, but they keep collecting and dumping data samples throughout that hour. In such case there are monitoring command-specific timestamps printed for each data sample. The following example shows how the cellsrvstat command uses ===Current Time=== to indicate the exact time the performance data below it is from. You can use this prefix in your custom scripts. Here’s an example:::

This output is just the first of each 5-second samples dumped by cellsrvstat every hour. The first column shows the cell metric name, and the second column (all zeros) shows the metric value in the current metric interval (snapshot). Because the command was just executed (and took its first sample), it shows zero for each metric, as the delta computation starts only after the second snapshot is taken. If you navigate downward in the OS Watcher dumpfile, you will see nonzero values for many metrics, starting from the second snapshot. The last column shows the cumulative value (since the cellsrv process started) for each metric. You probably should just ignore this cumulative value, as it contains information from since the cellsrv start (which may be months ago). Looking at a single cumulative value, accumulating information from such a long time, would not tell you much about what’s happening right now or what was happening last Friday at 8AM. Metric deltas over shorter time periods are the way to go, and this is what you see in the second column: the current interval value as of sampling the metrics. Now let’s say we are interested only in a single cellsrv metric, Number of Latency Threshold for Redo Log Writes, as the database layer experienced some log file parallel write delays (as seen in V$EVENT_HISTOGRAM, for example) earlier. Let’s say this happened on May 5, 2011 early in the morning. As the OS Watcher logfiles are named according the date and time (YY.MM.DD and hour in 24-hour format), you can search for specific files only by using regular Unix filesystem wildcards. In the following example we’re searching for all hours of May 5, 2011 and using egrep to list both the “current time” and the metric lines from the matching files:

As it’s hard to read the above output, here’s a little script which formats the output better and is more convenient to use:

While this script is meant to make extracting the desired metric history out of the OS Watcher logs easier, the main purpose of listing the script in this book is to show how easy extracting historical OS-level (and other) metrics can be. Investing a day into learning basic AWK or Perl text processing will likely pay off and save time when you need to do unconventional monitoring or troubleshooting tasks. Let’s see what it does:

The script goes through all the filenames, which match the second expression on the command line and greps for whatever metric is specified as the first parameter (in double quotes). In this case we are looking for Number of Latency Threshold Warnings for Redo Log Writes, which is incremented when I/O operations tagged as redolog file writes take too long to complete in the cell. Apparently there were two I/O operations around the time range between 00:00:18 and 00:00:23 which had response times high enough to be reported.

Using the previous example, you can already generate formatted data good enough for visual inspection or loading into Excel or some charting tool. If you are looking only for some random problem times, then you can do post-processing, such as showing just the lines where the metric value is not zero:

Alternatively, you can sort the output by the metric value in the CURRENT_VAL column to see the worst problem times first. The next example uses sort -nrk5 as we’re sorting the fifth column (columns 1–4 are the date column components, as far as the sort utility sees):

Apparently, the most log file write latency problems were detected at 6:00:03 AM May 14. When you look at the other output lines, you probably see an interesting pattern. All these problems are reported from a few seconds after a full hour. Well, this is just because in this particular Exadata testing cluster, we have over ten separate databases installed, but they only run some reports in parallel and usually there is no OLTP activity doing commits. But is it then doing these commits just after the hour starts? Well, these are default Oracle Database installations with AWR snapshots taking place at the full hour. And there are over 10 databases in the cluster, with an AWR snapshot taken and written in each cluster database instance. Each AWR snapshot write involves multiple commits, and apparently the resulting log file writes have occasionally taken longer than expected. The next step for troubleshooting such low-level I/O issues in a cell would be to look at the OS-level metrics, like iostat. The cells do perform regular block I/O against their disks, after all, so all the OS-level I/O monitoring tools still do apply.

In the following extract from the iostat archive, you see a few interesting things. The await time shows that on average, I/O completion time (queuing plus service time) is over 100ms for almost all the disks. For a couple of disks it is as high as 549 ms and 738 ms on average! The disk’s estimated service time (svctm) shows good I/O service times (below 10ms), so the hard disks and lower half of the I/O subsystem seems to work OK. The high response times must have come from I/O queuing waits, which happens when more I/O requests are issued to OS than the storage hardware (and device driver configuration) can accept.

This case is an example of how low-latency OLTP I/Os (like log file writes for commits) don’t go well together with large, massively parallel asynchronous I/O workloads, which drive the disk I/O queue lengths up, possibly making the low-latency I/Os suffer. This is why you should keep the I/O Resource Manager enabled in Exadata cells when running mixed workloads, as IORM is able to throttle the Smart Scan I/O and prioritize important background process I/O, such as log file writes, automatically.

You can read more about the OS Watcher tool in My Oracle Support article “OS Watcher User Guide” (Doc ID 301137.1). In fact, you can download the latest OS Watcher from there and use it for monitoring your other servers too. The My Oracle Support version of OS Watcher does not include the Exadata cell-specific monitoring scripts, but you don’t need those for your regular servers, anyway. For Exadata storage cells, you’ll have to keep using the original version shipped with the cell software, as Oracle doesn’t authorize installation of any additional storage into storage cells if you want to keep the supported configuration.

It pays off to open up and skim through OS Watcher scripts; you might learn some new useful OS-level monitoring commands from there and will have a better overview of which OS metrics are available. You should drill down to these low-level metrics when the more conveniently accessible Oracle Database and Cellcli-level metrics are not enough.

Summary

There are thousands of metrics that Oracle Database and the cells provide us. We’ve only touched on a small set of them here. This leads to the obvious questions: are all these metrics important? What should be their “good” values? Which ones should we act on? And so on. The general answer to all those questions is that no, you do not need to learn, memorize, and “tune” all of these metrics (it is impossible). You should always measure what matters – and it’s usually the response time. Ideally, you should start by measuring the end user response time and drill down where needed from there, sometimes to the database, sometimes to the application server or network metrics. It’s not always the database that is causing the trouble, you know. However, thanks to the complexity of modern multi-tier applications, this end-to-end diagnosis may not be available (and not feasible to implement).

In such case you would take a step downward and monitor the response time of your database queries and transactions. You just start the top-down approach from a little lower in the application stack, keeping in mind that the problem may still actually be happening somewhere in the application layer or higher. When monitoring the response times of your user reports and DW queries, you should probably start from the SQL Monitoring page (or ASH data), and identify the problem user’s query from there so you can drill down into it. Using the top-down approach and following the biggest time consumers in the SQL plan from there is much easier than the opposite bottom-up approach, where you might look at some database-wide top SQL report and hope to figure out what’s wrong with your specific user’s workload.

Of course, there are cases where you’ll be monitoring system-wide aggregated anonymous performance data (not tied to any specific user or session), as in capacity planning and utilization monitoring. However, questions like “Is my database performing well?” should never be answered by looking at some system utilization report. None of these tools can tell you whether your database system performs well; only your users can. And if the users are unhappy, you can start from an unhappy user and drill down into the response time from there. Oracle provides all the metrics you need!