Created on | Updated on

ログファイルを確認し、パフォーマンスをプロファイルする

ログファイルの場所に関してはこちらの記事をご参照ください。

ログファイルメッセージを解釈することを学ぶことは、レンダリングエラー、レンダリングの失敗、認識されないシェーディングノード、テクスチャの欠落などのレンダリングエラーを診断する場合に役立ちます。また、レンダリングのプロセスを深く理解し、レンダリングを最適化する方法をいつでも知ることができます。

初期化

ログファイルの最初の部分は、Redshiftのバージョン、パスの場所が記述されます。

INFO:    Redshift for Houdini plugin version 2.5.25
INFO:    Plugin compile time HDK version: 16.0.633
DETAILED:  Houdini host version: 16.0.688
INFO:    Plugin dso/dll and config path:
INFO:    Core data path: C:\ProgramData\Redshift
INFO:    Local data path: C:\ProgramData\Redshift
INFO:    Procedurals path: C:\ProgramData\Redshift\Procedurals
INFO:    Preferences file path: C:\ProgramData\Redshift\preferences.xml
INFO:    License path: C:\ProgramData\Redshift
DEBUG:   Registering the RS Shader nodes as Houdini VOP nodes
DETAILED: Main IPR open function
DEBUG:   Close scene
INFO:    Closing the RS scene
INFO:    Initializing the render session
DEBUG:   Querying texture cache buget from preferences.xml: 32 GB
DEBUG:   Querying cache path from preferences.xml: %LOCALAPPDATA%\Redshift\Cache
INFO:    Textures cache size (MB): 32768
INFO:    Textures cache path: %LOCALAPPDATA%\Redshift\Cache
DEBUG:   Creating cache path C:\Users\demo\AppData\Local\Redshift\Cache
DEBUG:   Enforcing shader cache budget...
DEBUG:   Enforcing texture cache budget...
DEBUG:   Creating mesh cache...
DEBUG:   Done
 
次に基本的なCPUとGPUの情報が記述されます。
 
INFO:    Devices enabled: 0:GeForce GTX 1080 Ti,1:GeForce GTX 1080 Ti,
INFO:    Shading package: Houdini
DETAILED: Redshift Initialized
DETAILED: Windows Platform (Windows 10 Home)
DETAILED: Release Build
DETAILED: Number of CPU HW threads: 12
DETAILED: CPU speed: 3.40 GHz
DETAILED: Total system memory: 31.89 GB
 
クィック診断をGPU毎に実行、PCIe(PCI Express)パフォーマンスが測定されます。下記のサンプルでは2つのGPUが搭載されているため、2つの診断が行われています。

ここで重要なのは、pinnedメモリバンド幅がだいたい5または6GB/s以上であることが重要です。PCIe(別名‘バス’)とは、GPUを残りのコンピュータと接続するコンピュータ部品ので、この部分がレンダリングパフォーマンスに影響します。あまり良くないマザーボードやハードディスクを使用している場合、PCIeパフォーマンスに悪影響を与え、レンダリングパフォーマンスを下げてしまいます。

全てのスロットにPCIe X 8以上を割り当てるようにしてください。
下記のサンプルでは、0番のGPUがPCIe X8で、1番目のGPUがPCIe X 16であることがわかります。
 
最後にレンダリングで使用可能なGPUメモリ量(通称“VRAM”)が記述され、この部分も非常に重要です。
下記のサンプルでは、11GBのメモリが搭載されていますが、その内9GBがRedshiftで使用できるということになります。
 
DETAILED: Creating CUDA contexts
DETAILED:   CUDA init ok
DETAILED:   Ordinals: { 0 1 }
DETAILED: Initializing GPUComputing module (CUDA). Ordinal 0
DETAILED:   CUDA Ver: 9000
DETAILED:   Device 1/2 : GeForce GTX 1080 Ti
DETAILED:   Compute capability: 6.1
DETAILED:   Num multiprocessors: 28
DETAILED:   PCI busID: 3, deviceID: 0, domainID: 0
DETAILED:   Theoretical memory bandwidth: 484.440002 GB/Sec
DETAILED:   Measured PCIe bandwidth (pinned CPU->GPU): 5.687099 GB/s
DETAILED:   Measured PCIe bandwidth (pinned GPU->CPU): 6.116644 GB/s
DETAILED:   Measured PCIe bandwidth (paged CPU->GPU): 3.517814 GB/s
DETAILED:   Measured PCIe bandwidth (paged GPU->CPU): 4.446193 GB/s
DETAILED:   Estimated GPU->CPU latency (0): 0.027751 ms
DETAILED:   Estimated GPU->CPU latency (1): 0.025484 ms
DETAILED:   Estimated GPU->CPU latency (2): 0.025608 ms
DETAILED:   Estimated GPU->CPU latency (3): 0.025401 ms
DETAILED:   New CUDA context created
DETAILED:   Available memory: 9309.7031 MB out of 11264.0000 MB
DETAILED: Initializing GPUComputing module (CUDA). Ordinal 1
DETAILED:   CUDA Ver: 9000
DETAILED:   Device 2/2 : GeForce GTX 1080 Ti
DETAILED:   Compute capability: 6.1
DETAILED:   Num multiprocessors: 28
DETAILED:   PCI busID: 4, deviceID: 0, domainID: 0
DETAILED:   Theoretical memory bandwidth: 484.440002 GB/Sec
DETAILED:   Measured PCIe bandwidth (pinned CPU->GPU): 11.064602 GB/s
DETAILED:   Measured PCIe bandwidth (pinned GPU->CPU): 12.194648 GB/s
DETAILED:   Measured PCIe bandwidth (paged CPU->GPU): 4.682428 GB/s
DETAILED:   Measured PCIe bandwidth (paged GPU->CPU): 7.278891 GB/s
DETAILED:   Estimated GPU->CPU latency (0): 0.035586 ms
DETAILED:   Estimated GPU->CPU latency (1): 0.031654 ms
DETAILED:   Estimated GPU->CPU latency (2): 0.028667 ms
DETAILED:   Estimated GPU->CPU latency (3): 0.028492 ms
DETAILED:   New CUDA context created
DETAILED:   Available memory: 9123.4063 MB out of 11264.0000 MB
 
 
 
シーン展開
 
次にシーンが展開されます。
ここではRedshiftが3DアプリケーションからデータをRedshift独自のメモリ内に取り込むプロセスが行われます。
シーン中に大量のオブジェクトやポリゴンがあると、展開に時間がかかるため、必要に応じてRedshift Proxyに変換してください。
 
(Houdiniサンプル)  
DEBUGVERBOSE: Loader threads farm released!
DEBUGVERBOSE: Function "RSHoudini_processExtractionList" over "(null)" execution time: 0.001 seconds
DEBUGVERBOSE: Function "RSHoudini_buildSceneRSInstanceMaterialOverrides" over "" execution time: 0.000 seconds
DEBUGVERBOSE: Function "RSHoudini_buildSceneRSMeshAndProxyInstances" over "" execution time: 0.000 seconds
DEBUGVERBOSE: Function "RSHoudini_buildSceneRSPointClouds" over "" execution time: 0.000 seconds
DEBUGVERBOSE: Function "RSHoudini_buildSceneRSVolumeGridInstances" over "" execution time: 0.000 seconds
DEBUGVERBOSE: Function "RSHoudini_buildSceneRSLightsInstances" over "" execution time: 0.000 seconds
DEBUGVERBOSE: Scene OBJ mesh nodes data loaded
DEBUGVERBOSE: Populating the internal scene lists
DEBUGVERBOSE: Linking the Meshes and Overrides in the loaded instance objects
DEBUGVERBOSE: Linking the Meshes and Overrides (or the Proxy objects) in the loaded point clouds objects
DEBUGVERBOSE: Scene loaded
DEBUGVERBOSE: Function "RSHoudini_loadScene" over "(null)" execution time: 1.133 seconds
 
(Mayaサンプル)
DEBUG: Initializing scene translator...
DEBUG: Time for log system initialization: 4 ms
DEBUG: Time for preferences loading: 1 ms
DEBUG: Time for renderer initialization: 1774 ms
DEBUG: Time for creation of feedback display: 3 ms
DEBUG: Time for shader translation map initialization: 22 ms
DEBUG: Time for dirty system initialization: 0 ms
DEBUG: Time for loading extensions: 86 ms
DEBUG: Time for node monitor initialization: 1 ms
DEBUG: Time for render interface creation: 1597 ms
DEBUG: Time for registration of maya nodes etc...: 54 ms
DEBUG: Time for node monitor start: 69 ms
DEBUG: Time for call to 'redshiftInit': 127 ms
INFO: Redshift for Maya 2017
INFO: Version 2.5.25, Aug 4 2017
INFO: Rendering frame 784
 
レンダリング - 準備段階
 
レンダリングでの最初のステップです。
レイトレーシング階層に対してシーンメッシュの最初のパス処理を行います。
次にシーンテクスチャに対してパスを処理し、変換する必要があるのか判断します。
 
レイトレーシング階層とは、レンダリングを高速化するためにレイトレーシング中に使用されるデータ構造のことです。そのため、レイトレーシング階層は非常に重要な段階となります。シーンに多数のオブジェクトやポリゴンが含まれている場合は、レイトレーシング階層構造に時間がかかることがあります。 
 

デフォルトでは、Redshiftはすべてのテクスチャを独自のフォーマットに変換します。この類の自動処理を回避したいのであれば、テクスチャプロセッサーを使用して、オフラインでテクスチャを事前処理します。

 
DEBUG: Preparing ray tracing hierarchy for meshes
DEBUG:   Time to process 5 meshes: 1.0s
DEBUG: Processing 2 textures
DEBUG: Time to process textures: 0.000813 seconds
DEBUG: Time to process all materials and shaders: 0.243697 seconds
DEBUG: Allocating GPU mem...(device 0)
DEBUG:   Done (CUDA reported free mem before: 8800 MB, after: 896 MB)
DEBUG: Allocating GPU mem...(device 1)
DEBUG:   Done (CUDA reported free mem before: 8628 MB, after: 1007 MB)
 
DEBUG: Allocating GPU mem for ray tracing hierarchy processing
DEBUG:   Allocating VRAM for device 0 (GeForce GTX 1080 Ti)
DEBUG:     Redshift can use up to 7904 MB
DEBUG:     Fixed: 0 MB
DEBUG:     Geo: 7473 MB, Tex: 21 MB, Rays: 409 MB, NRPR: 262144
DEBUG:     Done! ( 20ms). CUDA reported free mem: 896 MB
DEBUG:   Allocating VRAM for device 1 (GeForce GTX 1080 Ti)
DEBUG:     Redshift can use up to 7749 MB
DEBUG:     Fixed: 0 MB
DEBUG:     Geo: 7318 MB, Tex: 21 MB, Rays: 409 MB, NRPR: 262144
DEBUG:     Done! ( 15ms). CUDA reported free mem: 1007 MB
DEBUG:
 
DEBUG: Ray Tracing Hierarchy Info:
DEBUG:   Max depth: 128. MaxNumLeafPrimitives: 8
DEBUG:   Extents: (-7.014239 -0.000182 -6.500000) - (6.500000 6.724319 6.500000)
DEBUG:   Time to create tree: 2 ms (0 0 2)
 
 レンダリング - 事前パス
 
Redshiftは最終的なレンダリングを実行する前に、すべての事前パスを実行する必要があります。 
下記サンプルはIrradiance Point Cloudの計算となります。そのほかにSSS、Photon Mapping、Irradiance Cache、Subsurface Scatteringも事前パス計算が行われます。
 
各事前パスの開始時に、RedshiftはGPUのメモリ(VRAM)を設定する必要があります。下記の場合、RedshiftはDevice 0で約7.6GB、Device 1で7.3GBまでのVRAMを使用できます。これは実際に使用でき空きメモリよりも少なくなります。その理由は下記となります。
 
  • Redshiftは、GPUの空きVRAMの100%を使用しません。 デフォルトでは、90%を使用します。 しかし、Redshift Memoryタブでその割合を増減することができます。
  • Redshiftが初期化されると、その操作のためにいくらかVRAM(数十MB)が必要になります。このメモリはここではカウントされません。

VRAMが割り当てられた後、RedshiftはどのくらいのVRAMが割り当てられずに現在空いているのかプリントします。この場合、Device 0で896MB、Device 1で1007MBです。

 
DEBUG: Irradiance point cloud...
DEBUG: Allocating VRAM for device 0 (GeForce GTX 1080 Ti)
DEBUG:   Redshift can use up to 7904 MB
DEBUG:   Fixed: 134 MB
DEBUG:   Geo: 35 MB, Tex: 21 MB, Rays: 1795 MB, NRPR: 1127840
DEBUG:   Done! ( 21ms). CUDA reported free mem: 896 MB
DEBUG: Allocating VRAM for device 1 (GeForce GTX 1080 Ti)
DEBUG:   Redshift can use up to 7749 MB
DEBUG:   Fixed: 134 MB
DEBUG:   Geo: 35 MB, Tex: 21 MB, Rays: 1795 MB, NRPR: 1127840
DEBUG:   Done! ( 17ms). CUDA reported free mem: 1007 MB
DEBUG: Total num points before: 2493 (num new: 2493)
DEBUG: Total num points before: 2493 (num new: 2493)
DEBUG: Total num points before: 4400 (num new: 2041)
DEBUG: Total num points before: 4402 (num new: 2043)
DEBUG: Total num points before: 8198 (num new: 3798)
DEBUG: Total num points before: 8196 (num new: 3794)
DEBUG: Total num points before: 13862 (num new: 5664)
DEBUG: Total num points before: 13861 (num new: 5665)
DEBUG: Total num points before: 21963 (num new: 8101)
DEBUG: Total num points before: 21965 (num new: 8104)
DEBUG: Total num points before: 31688 (num new: 9725)
DEBUG: Total num points before: 31696 (num new: 9731)
DEBUG: Total num points before: 42415 (num new: 10727)
DEBUG: Total num points before: 42417 (num new: 10721)
DEBUG: Total num points before: 53375 (num new: 10960)
DEBUG: Total num points before: 53372 (num new: 10955)
DEBUG: Total num points before: 64531 (num new: 11156)
DEBUG: Total num points before: 64531 (num new: 11159)
DEBUG: Total irradiance point cloud construction time 7.2s
 
各事前パスの最後に計算時間がプリントされ、ここではSSS計算に7.2秒掛かったことがわかります。
 
レンダリング - 最終画像
 
Redshiftがイメージをブロック単位でレンダリングするレンダリングの最終段階となります。 ブロックは「バケット」とも呼ばれます。RedshiftはここでもVRAMの再割り当てを行います
 

ブロックレンダリングの全体的な進捗とそのブロックのレンダリングにかかった時間をプリントします。シーンの複雑さに応じて、ブロックによっては他のブロックよりもレンダリング時間がかかります。

 
 
DEBUG: Rendering blocks... (resolution: 1920x1080, block size: 128, unified minmax: [64,512])
DEBUG:   Allocating VRAM for device 0 (GeForce GTX 1080 Ti)
DEBUG:     Redshift can use up to 7904 MB
DEBUG:     Fixed: 1 MB
DEBUG:     Geo: 35 MB, Tex: 21 MB, Rays: 1747 MB, NRPR: 1127840
DEBUG:     Done! ( 22ms). CUDA reported free mem: 896 MB
DEBUG:   Allocating VRAM for device 1 (GeForce GTX 1080 Ti)
DEBUG:     Redshift can use up to 7749 MB
DEBUG:     Fixed: 1 MB
DEBUG:     Geo: 35 MB, Tex: 21 MB, Rays: 1747 MB, NRPR: 1127840
DEBUG:     Done! ( 16ms). CUDA reported free mem: 1007 MB
DEBUG: Block 1/135 (0,0) rendered by GPU 1 in 1299ms
DEBUG: Block 2/135 (1,0) rendered by GPU 0 in 1940ms
DEBUG: Block 3/135 (1,1) rendered by GPU 1 in 777ms
DEBUG: Block 4/135 (0,1) rendered by GPU 0 in 916ms
DEBUG: Block 5/135 (0,2) rendered by GPU 1 in 1245ms
DEBUG: Block 7/135 (1,3) rendered by GPU 1 in 837ms
.
.
DEBUG: Time to render 135 blocks: 1m:4s
INFO: Rendering time: 1m:14s (2 GPU(s) used)
 
 
統計情報
最後に統計情報がプリントされます。ここは、ログファイルで最も重要な部分となります。例えばプロキシの数、メッシュ、ライト、固有ポリゴン、インスタンスによるポリゴンなど色々なシーンの統計情報が含まれています。
統計情報を確認すると、シーンを分析をする時に役立ちます。
 
シーン内に存在する固有ポリゴンの数を簡単に調べることもできます。「固有」とは「インスタンス化されていない」ことを意味します。
 
DEBUG: Scene statistics
DEBUG:  
DEBUG:   General counts
DEBUG:     Proxies: 0
DEBUG:     Proxy instances: 0
DEBUG:     Meshes: 5 (5 TriMeshes, 0 HairMeshes)
DEBUG:     Instances: 5
DEBUG:     Point cloud points: 0
DEBUG:     Lights: 3
DEBUG:     Volume grids: 0 (0 unique)
DEBUG:     Sprite textures: 0
DEBUG:  
DEBUG:   Geometry
DEBUG:     Unique triangles pre tessellation: 600198
DEBUG:     Unique triangles post tessellation: 600198
DEBUG:     Unique points: 0
DEBUG:     Unique hair strands: 0
DEBUG:     Unique hair strand segments: 0
DEBUG:     Total triangles: 600198
DEBUG:     Total points: 0
DEBUG:     Total hair strands: 0
DEBUG:     Total hair strand segments: 0
DEBUG:
DEBUG:   Largest triangle meshes:
DEBUG:         600000 triangles : /obj/chocolates
DEBUG:         162 triangles : /obj/Floor
DEBUG:         32 triangles : /obj/rslight1
DEBUG:         2 triangles : /obj/rslight2
DEBUG:         2 triangles : /obj/rslight3
 
最も重要な情報は、GPUメモリ参照するものです。下記GPU Memoryにある「uploads」の数字は、データをGPUに送信するのに必要だったPCIeトラフィック量となります。理由は、 Redshiftは、絶対に必要なデータのみをGPUに送信するからです。
 
DEBUG:   GPU Memory
DEBUG:         Device 0 geometry PCIe uploads: 29.88 MB (cachesize: 35.87 MB)
DEBUG:         Device 0 texture PCIe uploads: 13.02 MB (cachesize: 21.42 MB)
DEBUG:         Device 1 geometry PCIe uploads: 29.88 MB (cachesize: 35.87 MB)
DEBUG:         Device 1 texture PCIe uploads: 13.03 MB (cachesize: 21.42 MB)
DEBUG:         Matrices (for instances/points): 240 B
DEBUG:         Rays: 1.71 GB
DEBUG:         Sprite textures: 0 B
DEBUG:         Volume grids: 0 B
DEBUG:  
DEBUG:   Textures
DEBUG:     Device 0 stream and upload time: 25ms
DEBUG:         File loading time: 1ms
DEBUG:         File decompression time: 7ms
DEBUG:         File data amount: 574.28 KB (66 file accesses, 25 file seeks)
DEBUG:         Decompressed loaded amount: 16.50 MB (cachesize: 4.00 GB)
DEBUG:         File read throughput: 332.28 MB/s
DEBUG:         Average GPU cache hits: 99%
DEBUG:     Device 1 stream and upload time: 19ms
DEBUG:         File loading time: 0ms
DEBUG:         File decompression time: 1ms
DEBUG:         File data amount: 87.18 KB (20 file accesses, 17 file seeks)
DEBUG:         Decompressed loaded amount: 5.00 MB (cachesize: 4.00 GB)
DEBUG:         File read throughput: 520.57 MB/s
DEBUG:        Average GPU cache hits: 99%
 
GPU Ray Accel. And Geometry Memory Stats の数字は、シーン内のポリゴンとスプライン(プリミティブ)についての情報です。これらの数字の合計は、「out-of-core-access」を必要とせずに、全てのプリミティブが収まるために必要なGPUメモリの大きさを表します。
 
DEBUG:     GPU Ray Accel. And Geometry Memory Stats (rough)
DEBUG:         Acceleration Structures: 7.93 MB
DEBUG:         Main primitive data: 7.84 MB
DEBUG:         Extra primitive data: 13.58 MB
DEBUG:         Primitive loading time: 10ms
 
「out-of-core access」(またはその他の理由で)により、GPUにデータを再送信する必要がある場合もあります。その場合、「uploads」は「GPU Ray Accel. And Geometry Memory Stats」の合計より大きくなる可能性があります。パフォーマンスプロファイル時に、”uploads"の数字が、「何ギガバイト」にも突入するのであれば、特に注意が必要です。
 
 
 

問題が解決しない場合は、Born Digital サポートまでお問い合わせ下さい。

※ 問い合わせ対応はBorn Digitalより製品をご購入頂きましたお客様のみのサービスとなります。ご了承下さい。
サポート問い合わせ