DBQL（データベース クエリー ログ）

# DBQLとは
SQL単位の性能情報ログ
Oracleのv$sqlやDBA_HIST_SQLSTATに近いが、SQL単位でサマライズされず、1実行毎に性能情報を確認可能。
取得対象を事前に設定しておく必要がある。

# コマンド
| 操作 | コマンド | 実行例・補足|
|:-:|:-:|:-:|
| 全てのルールを確認 | SELECT * FROM DBC.DBQLRULESV;  |
| 「全て」に有効なルールを確認 | SHOW QUERY LOGGING ON ALL;  |
| データベースのルールを確認  | SHOW QUERY LOGGING ON [データベース名];  |
| ロギングの開始  | BEGIN QUERY LOGGING ON [データベース名];  |
| DBQL確認(メインログ)  | select * from DBC.QryLogV;  |
| 特定のDBQL確認  | select * from DBC.QryLogV where QueryID = [クエリID];  ||

# 実行例
### ルールを確認
各ルールの意味は[DBQLRulesV](https://docs.teradata.com/reader/fMqp0D_uNdzh8~BHZ2S~9w/hNAIND7lhRYRL~zDzA3qXw)参照

```
show query logging on all;

 *** Text of DDL statement returned. 
 *** Total elapsed time was 1 second.

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

    Rule UserName   "ALL" (From an ALL rule)
      Rule UserId   00000000
      Rule ZoneId   00000000
          Account   (Rule for any Account)

       DBQL RULE:
          Explain   F
           Object   F
              SQL   F
             Step   F
          XMLPlan   F
       StatsUsage   F
         UseCount   F
            Param   F
     FeatureUsage   F
          Verbose   F
     StatsDetails   F
      UtilityInfo   F
        NoColumns   F
          Summary   F
        Threshold   F
```


## ロギングの開始
全てのユーザに対するロギングを開始する場合

>begin query logging on all;

```
begin query logging on all;

 *** Begin querylog accepted. 
 *** Total elapsed time was 1 second.

select * from dbc.dbqlrulesv;

UserName
---------------------------------------------------------------------------
All

```

## 特定のDBQL確認
事前にfoldlineとsidetitlesを設定

```
.foldline;
.sidetitles;
```

```
select * from dbc.qrylogv where queryid = 307190827503924304;

 *** Query completed. One row found. 128 columns returned. 
 *** Total elapsed time was 1 second.

 *** Warning: Report has more than 100 column(s).
              Only the first 100 column(s) will be displayed.

                  ProcID  30719
        CollectTimeStamp 2020-09-02 10:52:09.040000
                 QueryID   307190827503924304
                  UserID 00000804
                UserName SYSDBA
         DefaultDatabase SYSDBA
              AcctString DBC
        ExpandAcctString DBC
               SessionID          1,006
           LogicalHostID      1
              RequestNum            119
      InternalRequestNum            119
                 TxnUniq ?
               LockLevel ?
           LogonDateTime 2020-08-22 12:11:56.360000
          AcctStringTime        ?
          AcctStringHour      ?
          AcctStringDate        ?
             LogonSource (TCP/IP) c676 127.0.0.1 DBC     14592  ROOT  BTEQ  01 LSS
                   AppID BTEQ
                ClientID ROOT
              ClientAddr 127.0.0.1
               QueryBand =S> BLOCKCOMPRESSION=NO;
               ProfileID ?
               StartTime 2020-09-02 10:51:47.140000
           FirstStepTime 2020-09-02 10:51:47.540000
           FirstRespTime 2020-09-02 10:52:26.580000
             ElapsedTime     0:00:39.440000
                NumSteps       5
            NumStepswPar       0
           MaxStepsInPar       0
           NumResultRows            4,194,309
      NumResultOneMBRows                    0
         MaxOneMBRowSize              0
            TotalIOCount                  665
              AMPCPUTime         16.568
           ParserCPUTime          0.032
        UtilityByteCount                          ?
         UtilityRowCount                    ?
               ErrorCode              0
               ErrorText ?
             WarningOnly
               AbortFlag
               CacheFlag
           StatementType Select
          StatementGroup Select
               QueryText select * from t1;
         NumOfActiveAMPs              2
           MaxAMPCPUTime         16.568
         MaxCPUAmpNumber              0
           MinAmpCPUTime          0.000
                MaxAmpIO                  661
          MaxIOAmpNumber              0
                MinAmpIO                    4
              SpoolUsage                755,171,328
                     LSN              ?
           EstResultRows            4,194,309
             EstProcTime         11.314
          EstMaxStepTime     11,313.656
          EstMaxRowCount            4,194,309
         TDWMEstMemUsage          4.000
          AMPCPUTimeNorm        665.039
       ParserCPUTimeNorm          1.284
       MaxAMPCPUTimeNorm        665.039
     MaxCPUAmpNumberNorm              0
       MinAmpCPUTimeNorm          0.000
            ParserExpReq          0.117
               ProxyUser ?
               ProxyRole ?
SessionTemporalQualifier ?
            CalendarName TERADATA
           CPUDecayLevel       0
            IODecayLevel       0
    TacticalCPUException              0
     TacticalIOException              0
             SeqRespTime         39.040
                 ReqIOKB    794,584.000
               ReqPhysIO         34.000
             ReqPhysIOKB      2,372.000
          DataCollectAlg    1
        CallNestingLevel    0
           NumRequestCtx    1
                KeepFlag N
           QueryRedriven N
             ReDriveKind ?
            LastRespTime                          ?
              DisCPUTime                    0.004
              Statements              1
          DisCPUTimeNorm                    0.161
                 TxnMode BTET
             RequestMode Exec
              DBQLStatus              ?
            NumFragments              ?
             VHLogicalIO                    0.000
                VHPhysIO                    0.000
           VHLogicalIOKB                    0.000
              VHPhysIOKB                    0.000
               LockDelay                        ?
           CheckpointNum                    0
               UnityTime                    0.000


```



# DBQL内容例（DBC.QryLogV）
420万件のレコードに対するフルスキャンを実行した場合の内容例
select * from t1;

| カラム | 値（例） | 内容 |
|:-:|:-:|:-:|
| ProcID  | 30719  | SQLが実行されたPE(Processing Engine)のID  |
| CollectTimeStamp  | 2020-09-02 10:52:09  | クエリログが取得された時間  |
| QueryID  | 307190827503924304  | クエリID  |
| UserID  | 0x00000804  | ユーザID  |
| UserName  | SYSDBA  | ユーザ名  |
| DefaultDatabase  | SYSDBA  | デフォルトDB  |
| AcctString  | DBC  | ユーザーがクエリーを発行した拡張アカウント文字列 |
| ExpandAcctString  | DBC  | ユーザーの拡張ログオン列 |
| SessionID  | 1006  |  セッションID |
| LogicalHostID  | 1 |  論理ホストID |
| RequestNum| 119 |  セッション内でクエリがリクエストされた番号 |
| InternalRequestNum| 119 |  ストアドプロシージャが実行された際の内部リクエスト番号 |
| TxnUniq| | ProcIdで使用されるトランザクション固有の部分 |
| LockLevel| | このリクエストに関連付けられた最高レベルのロック |
| LogonDateTime| 2020-08-22 12:11:56 | ユーザがログオンした日時 |
| AcctStringTime | | ユーザーが拡張アカウント文字列(ASE)を指定したときの&Tコードの結果 |
| AcctStringHour| | ユーザーが拡張アカウント文字列(ASE)を指定したときの&Hコードの結果 |
| AcctStringDate| | ユーザーが拡張アカウント文字列(ASE)を指定したときの&Dコードの結果 |
| LogonSource| (TCP/IP) c676 127.0.0.1 DBC     14592  ROOT  BTEQ  01 LSS | クエリを発行したログオンソース |
| AppID | BTEQ | クエリを発行したアプリケーションID |
| ClientID | ClientID | クエリを発行したクライアントID |
| ClientAddr | 127.0.0.1 | クエリを発行したクライアントアドレス |
| QueryBand | =S> BLOCKCOMPRESSION=NO; | クエリバンド値 |
| ProfileID |  | クエリを発行したプロファイルID |
| StartTime | 2020-09-02 10:51:47 | クエリが発行された時間 |
| FirstStepTime | 2020-09-02 10:51:48 | クエリが実行（ディスパッチ）開始された時間 |
| FirstRespTime | 2020-09-02 10:52:27 | ホストに最初の返答があった時間 |
| ElapsedTime | 0:00:39 | 実行時間。実行開始から最初の返答があるまでの時間。実行完了までを指すOracleのElapsedTimeとは異なる。 |
| NumSteps | 5 | クエリーの(レベル1)ステップの合計数 |
| NumStepswPar | 0 | 並列ステップを持つ(レベル1)ステップの数 |
| MaxStepsInPar | 0 | クエリーに関して並列的に行なわれる(レベル2)ステップの最大数 |
| NumResultRows | 4194309 | クエリーで返された総行数 |
| NumResultOneMBRows | 0 | クエリーに返される一連の行内の1MB行(1MB > size > 64KB)の数 |
| MaxOneMBRowSize | 0 | クエリーで返される一連の行における最大1MB行の実際のバイト数 |
| TotalIOCount | 665 | クエリーで生成されたAMPのIOの数（論理） |
| AMPCPUTime | 16.568 | このクエリーで使用されるAMP CPU合計時間(秒)。全てのAMPのCPU時間合計。 |
| ParserCPUTime | 0.032 | クエリーに使用された構文解析プログラムとディスパッチャの合計CPU時間(秒) |
| UtilityByteCount |  | FastLoadジョブまたはMultiLoadジョブの一部としてクライアントで転送されたバイト数 |
| UtilityRowCount |  | FastLoadまたはMultiLoadで読み込まれた行数 |
| ErrorCode | 0 | エラー コード |
| ErrorText |  | エラーのテキスト |
| WarningOnly |  | 警告モードでTDWM（Teradata Dynamic Workload Management）の実行中にエラーが報告された場合、またはまったくログに記録されていない場合は、警告コードTにtrueを返します。WarningOnlyがtrueでない場合は、フィールドにNULLがあります。 |
| AbortFlag |  | アボートされた場合のフラグ |
| CacheFlag |  | クエリーが[リクエスト キャッシュ](https://docs.teradata.com/reader/bPAhBMHKVHoOyXgxwdlT2Q/CdW2swiPMxJrBnbecgDVMA)（※）にない場合は空白。（※）PEローカル メモリ内バッファであり、このバッファの中に、DML(データ操作言語)リクエストの構文解析時に生成されたステップが格納されます。|
| StatementType | Select | クエリーで実行された文のタイプ |
|StatementGroup  | Select  | DDL、DML、またはSELECT |
| QueryText | select * from t1; | クエリー テキスト。デフォルトは２００文字。 |
| NumOfActiveAMPs | 2 | このクエリーでアクティブなAMPの数 |
| MaxAMPCPUTime | 16.568 | クエリーでCPU使用率が最も高かったAMPのCPU時間(秒) |
| MaxCPUAmpNumber | 0 | CPU使用率が最も高かったAMP番号。 |
| MinAmpCPUTime | 0 | ステップでCPU使用率が最も低かったAMPのCPU時間(秒) |
| MaxAmpIO | 661 | ステップでI/O利用率が最も高かったAMP |
| MaxIOAmpNumber | 0 | ステップでI/O使用量が最も高かったAMP番号 |
| MinAmpIO | 4 | クエリーでI/Oが最も低かったI/Oカウント |
| SpoolUsage | 755171328 | クエリーでスプールに使用されたバイト数 |
| LSN |  | ロード ユーティリティの場合に使用 |
| EstResultRows | 4194309 | このクエリーで返される行の推定数。→実際の結果行（NumResultRows）と同じ。 |
| EstProcTime | 11.31365571 | 最適化ルーチンからの推定処理秒数(0.001秒単位) |
| EstMaxStepTime | 11313.65571 | 最適化ルーチンからの最大ステップ推定時間(秒) |
| EstMaxRowCount | 4194309 | このクエリーのステップの最大推定行数 |
| TDWMEstMemUsage | 4 | 最大ステップの最大推定メモリ(MB)。 |
| AMPCPUTimeNorm | 665.039 | このクエリーで使用されたAMP CPU正規化合計時間(秒) ※正規化（Normalized）：異なるハード間での比較のため、CPUの性能に応じて一定の値（今回は40）を乗じたもの。|
| ParserCPUTimeNorm | 1.284 | 正規化された構文解析プログラムCPU時間(秒) |
| MaxAMPCPUTimeNorm | 665.039 | AMPの正規化された最大CPU時間(秒) |
| MaxCPUAmpNumberNorm | 0 | CPU使用率が最も高かったAMP番号 |
| MinAmpCPUTimeNorm | 0 | AMPの正規化された最小CPU時間(秒) |
| ParserExpReq| 0.117037 | 計測した構文解析プログラムexpリクエストで経過した時間(1/100秒) ( |
| （中略） |  |  |
| SeqRespTime | 39.04 | すべてのステップが順に実行されたと仮定した場合の、応答時間の合計秒数 |
| ReqIOKB | 794584 | リクエストの論理IO使用量の合計キロバイト数 |
| ReqPhysIO | 34 | リクエストの物理I/O数 |
| ReqPhysIOKB | 2372 | リクエストの物理IO使用量の合計キロバイト数 |
| （中略） |  |  |
| MaxStepMemory | 0.187497139 | リクエストのいずれかのステップで使用される最大メモリ(MB) |
| （中略） |  |  |
| UsedIota | 33189000 | リクエストで使用されるIOトークンを返します。※IOTA=Input/Output Token Allocations |

# 結果整理
### 時間
CPU時間（AMPCPUTime）：16.568秒（AMP#0：16.568秒、AMP#1：0秒）
応答時間の合計（SeqRespTime）：39.04秒

### I/O
論理IO（TotalIOCount）：665回（AMP#0：661回、AMP#1：4回）
リクエストの物理I/O数：34回
論理IO使用量（ReqIOKB）：800MB
物理IO使用量（ReqPhysIOKB）：2.3MB


以下の記載があるので、論理IO使用量（ReqIOKB）と物理IO使用量（ReqPhysIOKB）の比較ではキャッシュヒット率は出ない？
>ResUsageデータは、論理I/Oの合計数と結果的に物理I/OになったI/Oリクエスト数を比較してキャッシュのヒット率を判断するのに役立ちます。DBQLデータは論理I/Oのみを追跡するため、DBQLデータとResUsageデータを一致させると混乱が生じる可能性がありますが、比較によってこのような混乱を回避できます。
[ResUsageとキャッシュのヒット率 • Teradata Vantage™ - データベースの管理 • リーダー • Teradataドキュメント]
(https://www.docs.teradata.com/reader/0rYfghiYcBZf2Y_ffU5UtA/g5iNObxkSysa2cbvQYGsEw)

### メトリクス（PJIとUII）
#### PJI（Product Join Indicator　：　直積インジケータ）
算出式　：　(AMPCPUTime * 1000)/TotalIOCount 
I/Oに対するCPU使用量。高い場合は直積などが発生している可能性がある。3以上で高いとされる。

（例）16.568秒　* 1000 / 665回 = 24.9

#### UII（Unnecessary I/O Indicator　：　不要IOインジケータ）
算出式　：　TotalIOCount / (AMPCPUTime * 1000)
CPU使用量に対するI/O。高い場合は少ない結果行を取得するためにフルスキャンが発生しており索引の付与が有効な可能性がある。

（例）665回 / （16.568秒　* 1000） = 0.04

### 容量
表容量：100MB（伸張後：450MB）
スプール利用量（SpoolUsage）：750MB
メモリ利用量(MaxStepMemory)：0.2MB




# 参考
[現在のルールの表示または終了 • Teradata Vantage™ - データベースの管理 • リーダー • Teradataドキュメント]
(https://docs.teradata.com/reader/0rYfghiYcBZf2Y_ffU5UtA/BGtZslufjN_j15ueWSARyw)
[ロギング文 • Teradata Vantage™ SQLデータ定義言語 構文規則および例 • リーダー • Teradataドキュメント]
(https://docs.teradata.com/reader/RknaJAFX_2CtUAZfB4_rTA/YENx89CDXxOhCQxNUgm65A)
[データベース ログについて • Teradata Vantage™ - データベースの管理 • リーダー • Teradataドキュメント]
(https://docs.teradata.com/reader/0rYfghiYcBZf2Y_ffU5UtA/SKXxl~CbpOZ_3HgIzG7usA)
[QryLogV • Teradata Vantage™ データ ディクショナリ • リーダー • Teradataドキュメント]
(https://docs.teradata.com/reader/fMqp0D_uNdzh8~BHZ2S~9w/OXXoK11F6pcW~NQshfKzWA)
[DBQLRulesV • Teradata Vantage™ データ ディクショナリ • リーダー • Teradataドキュメント](https://docs.teradata.com/reader/fMqp0D_uNdzh8~BHZ2S~9w/hNAIND7lhRYRL~zDzA3qXw)
[Suspect Query Formulas • Teradata® Viewpoint User Guide • リーダー • Teradataドキュメント](https://www.docs.teradata.com/r/LzJ4E~8~tgVsMLW1~wBJGA/5Fu7UQ5W0NsTDv_5ivLbdg)
[UII and PJI? | Teradata Downloads](https://downloads.teradata.com/forum/analytics/uii-and-pji)