09 ASH

정의 / 특징


ASH = Active Session History
ORACLE 10g 이상 사용 가능.

"짧은 시간 동안 발생한 문제를 파악하는데 유용"

AWR 데이터에 비해 수집되는 정보의 종류가 적음.
샘플 세션만 저장되므로 성능 문제 발생 시 이에 대한 데이터가 없을 수 있음.

사용


SYS> @?/rdbms/admin/ashrpt.sql

Enter value for report_type: [html(default) / text]
Enter value for begin_time: [측정 시작점 /Defaults to -15 mins]
Enter value for duration: [측정 구간 시간]
Enter value for report_name:

Report


ASH Report For ORCL/orcl

DB Name         DB Id    Instance     Inst Num Release     RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
ORCL          1457022532 orcl                1 11.2.0.4.0  NO  db01

CPUs           SGA Size       Buffer Cache        Shared Pool    ASH Buffer Size
---- ------------------ ------------------ ------------------ ------------------
   2        597M (100%)       416M (69.6%)       160M (26.8%)        4.0M (0.7%)


          Analysis Begin Time:   16-Dec-16 23:56:08
            Analysis End Time:   17-Dec-16 00:06:08
                 Elapsed Time:        10.0 (mins)
            Begin Data Source:   V$ACTIVE_SESSION_HISTORY
              End Data Source:   V$ACTIVE_SESSION_HISTORY
                 Sample Count:           8
      Average Active Sessions:        0.01
  Avg. Active Session per CPU:        0.01
                Report Target:   None specified

Top User Events                    DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                                                               Avg Active
Event                               Event Class        % Event   Sessions
----------------------------------- --------------- ---------- ----------
CPU + Wait for CPU                  CPU                  12.50       0.00
          -------------------------------------------------------------

Top Background Events              DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                                                               Avg Active
Event                               Event Class     % Activity   Sessions
----------------------------------- --------------- ---------- ----------
CPU + Wait for CPU                  CPU                  87.50       0.01
          -------------------------------------------------------------

Top Event P1/P2/P3 Values          DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------

Top Service/Module                 DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

Service        Module                   % Activity Action               % Action
-------------- ------------------------ ---------- ------------------ ----------
SYS$BACKGROUND UNNAMED                       75.00 UNNAMED                 75.00
               MMON_SLAVE                    12.50 Auto-Flush Slave A      12.50
SYS$USERS      UNNAMED                       12.50 UNNAMED                 12.50
          -------------------------------------------------------------

Top Client IDs                     DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------

Top SQL Command Types              DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)
-> 'Distinct SQLIDs' is the count of the distinct number of SQLIDs
      with the given SQL Command Type found over all the ASH samples
      in the analysis period

                                           Distinct            Avg Active
SQL Command Type                             SQLIDs % Activity   Sessions
---------------------------------------- ---------- ---------- ----------
INSERT                                            1      12.50       0.00
SELECT                                            1      12.50       0.00
          -------------------------------------------------------------

Top Phases of Execution            DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                                          Avg Active
Phase of Execution             % Activity   Sessions
------------------------------ ---------- ----------
SQL Execution                       12.50       0.00
          -------------------------------------------------------------


Top SQL with Top Events           DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                                                        Sampled #
                 SQL ID             Planhash        of Executions     % Activity
----------------------- -------------------- -------------------- --------------
Event                          % Event Top Row Source                    % RwSrc
------------------------------ ------- --------------------------------- -------
          36z7c4rvtpkw7                  N/A                    0          12.50
CPU + Wait for CPU               12.50 ** Row Source Not Available **      12.50
** SQL Text Not Available **

          3nkd3g3ju5ph1           2853959010                    1          12.50
CPU + Wait for CPU               12.50 INDEX - RANGE SCAN                  12.50
select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spar
e2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is nul
l and linkname is null and subname is null

          -------------------------------------------------------------

Top SQL with Top Row Sources       DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                                                        Sampled #
                 SQL ID             PlanHash        of Executions     % Activity
----------------------- -------------------- -------------------- --------------
Row Source                               % RwSrc Top Event               % Event
---------------------------------------- ------- ----------------------- -------
          36z7c4rvtpkw7                  N/A                    0          12.50
** Row Source Not Available **             12.50 CPU + Wait for CPU        12.50
** SQL Text Not Available **

          3nkd3g3ju5ph1           2853959010                    1          12.50
INDEX - RANGE SCAN                         12.50 CPU + Wait for CPU        12.50
select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spar
e2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is nul
l and linkname is null and subname is null

          -------------------------------------------------------------

Top SQL using literals             DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------

Top Parsing Module/Action          DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------

Top PL/SQL Procedures              DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)
-> 'PL/SQL entry subprogram' represents the application's top-level
      entry-point(procedure, function, trigger, package initialization
      or RPC call) into PL/SQL.
-> 'PL/SQL current subprogram' is the pl/sql subprogram being executed
      at the point of sampling . If the value is 'SQL', it represents
      the percentage of time spent executing SQL for the particular
      plsql entry subprogram

PLSQL Entry Subprogram                                            % Activity
----------------------------------------------------------------- ----------
PLSQL Current Subprogram                                           % Current
----------------------------------------------------------------- ----------
SYSMAN.EMD_MAINTENANCE.EXECUTE_EM_DBMS_JOB_PROCS                       12.50
   SQL                                                                 12.50
          -------------------------------------------------------------

Top Java Workload                  DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------

Top Call Types                     DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------


Top Sessions                      DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)
-> '# Samples Active' shows the number of ASH samples in which the session
      was found waiting for that particular event. The percentage shown
      in this column is calculated with respect to wall clock time
      and not total database activity.
-> 'XIDs' shows the number of distinct transaction IDs sampled in ASH
      when the session was waiting for that particular event
-> For sessions running Parallel Queries, this section will NOT aggregate
      the PQ slave activity into the session issuing the PQ. Refer to
      the 'Top Sessions running PQs' section for such statistics.

   Sid, Serial# % Activity Event                             % Event
--------------- ---------- ------------------------------ ----------
User                 Program                          # Samples Active     XIDs
-------------------- ------------------------------ ------------------ --------
      126,    1      62.50 CPU + Wait for CPU                  62.50
SYS                  oracle@db01 (PSP0)                   5/600 [  1%]        0

      125, 1051      12.50 CPU + Wait for CPU                  12.50
SYS                  oracle@db01 (M000)                   1/600 [  0%]        0

      132,    1      12.50 CPU + Wait for CPU                  12.50
SYS                  oracle@db01 (MMON)                   1/600 [  0%]        0

      135, 1221      12.50 CPU + Wait for CPU                  12.50
SYS                  oracle@db01 (J000)                   1/600 [  0%]        0

          -------------------------------------------------------------

Top Blocking Sessions              DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------


Top Sessions running PQs          DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------

Top DB Objects                     DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------

Top DB Files                       DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------

Top Latches                        DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)

                  No data exists for this section of the report.
          -------------------------------------------------------------


Activity Over Time                DB/Inst: ORCL/orcl  (Dec 16 23:56 to 00:06)
-> Analysis period is divided into smaller time slots
-> Top 3 events are reported in each of those slots
-> 'Slot Count' shows the number of ASH samples in that slot
-> 'Event Count' shows the number of ASH samples waiting for
   that event in that slot
-> '% Event' is 'Event Count' over all ASH samples in the analysis period

                         Slot                                   Event
Slot Time (Duration)    Count Event                             Count % Event
-------------------- -------- ------------------------------ -------- -------
23:56:08   (52 secs)        1 CPU + Wait for CPU                    1   12.50
23:58:00   (1.0 min)        1 CPU + Wait for CPU                    1   12.50
00:00:00   (1.0 min)        2 CPU + Wait for CPU                    2   25.00
00:01:00   (1.0 min)        1 CPU + Wait for CPU                    1   12.50
00:03:00   (1.0 min)        1 CPU + Wait for CPU                    1   12.50
00:04:00   (1.0 min)        1 CPU + Wait for CPU                    1   12.50
00:05:00   (1.0 min)        1 CPU + Wait for CPU                    1   12.50
          -------------------------------------------------------------

End of Report

  • Ratio 기반 분석 방법론의 한계점은,
    시스템에 문제가 있는 것으로 진단되었을 때 그 원인을 찾아 실제 문제를 해결하는 데까지 많은 시간이 걸리는 데 있음.
  • 대기 이벤트 기반 분석 방법론을 사용하더라도 마찬가지임.
    대기 이벤트 발생량과 대기 시간을 통해 문제의 원인을 금방 알 수는 있지만,
    실제 문제를 해결하려면 구체적으로 어떤 프로그램에서 문제를 일으켰고,
    어떤 세션에서 성능 때문에 고생했는지를 확인할 수 있어야 함.
  • 시스템 레벨에서 분석하고 해결할 수 있는, 구조적인 문제들도 있음.
    대개는 세션 레벨의 성능분석을 요함.
  • 오라클은 현재 접속해서 활동 중인 Active 세션 정보를 1초에 한번씩 샘플링해서 ASH 버퍼에 저장함.
  • SGA Shared Pool에서 CPU당 2MB의 버퍼를 할당 받아 세션 정보를 기록하며, 1시간 혹은 버퍼의 2/3가 찰 때마다 AWR에 저장됨.
  • 현재 발생 중인 대기 이벤트의 Wait Class가 Application, Concurrency, Cluster, User I/O일 때만 의미 있는 값임을 알아야 함.
  • ITL 슬롯 부족 때문에 발생하는 enq: TX - allocate ITL entry 대기 이벤트는
    Configuration에 속하므로, v$active_session_history 뷰를 조회할 때 함께 출력되는 오브젝트에 Lock이 걸렸다고 판단해서는 안됨.
    대개 그럴 때는 오브젝트 번호가 -1로 출력되지만 직전에 발생한 이벤트의 오브젝트 정보가 계속 남아서 보이는 경우가 있으므로 잘못 해석하지 않도록 주의해야 함.
  • 초 단위로 쓰기가 발생하는 ASH 버퍼를 읽을 때 래치를 사용한다면 경합이 생길 수 있음.
    오라클은 ASH 버퍼를 읽는 세션에 대해서는 래치를 요구하지 않으며, 그 때문에 간혹 일관성 없는 잘못된 정보가 나타날 수도 있음.
  • ASH 기능을 이용하면 현재뿐 아니라 과거시점에 발생한 장애 및 성능 저하 원인까지 세션 레벨로 분석할 수 있음.
  • v$active_session_history 정보를 AWR 내에 보관하므로 과거치에 대한 세션 레벨 분석이 가능.
  • SGA를 DMA(Direct Memory Access) 방식으로 액세스하기 때문에 가능. 1/10만 샘플링해서 저장.
  • 문제가 되는 대기 이벤트는 일정간격을 두고 지속적으로 발생하기 때문에 샘플링된 자료만으로도 원인을 찾는데 큰 지장은 없음.
  • v$active_session_history를 조회했을 때 정보가 찾아지지 않는다면
    이미 AWR에 쓰여진 것이므로 dba_hist_active_sess_history 뷰를 조회하면 됨.

추적 및 탐색


1. dba_hist_system_event 조회, 다량으로 발생된 이벤트를 확인.
2. dba_hist_active_sess_history 조회, 해당 이벤트를 많이 대기한 세션을 확인.
3. 블로킹 세션 정보로 dba_hist_active_sess_history 재조회.
4. 블로킹 세션이 찾아지면 해당 세션이 그 시점에 어떤 작업을 수행 중이었는지 확인.
5. sql_id를 이용해 그 당시 SQL과 실행계획까지 확인. v$sql 및 v$sql_plan이 AWR에 저장되기 때문.