log file sync的再次思考

﹏ヽ暗。殇╰゛Y 2022-08-17 14:25 17阅读 0赞

昨天系统整体慢，最终定位到是数据库层面的问题。在TOP的等待事件中可以看到log file sync平均等待达到了157，根据之前的经验这个值超过20就有性能问题。

如果按照以前的诊断思路，就是认定服务器的IO有问题，建议用IO快一点的存储。

不过通过这次问题的解决，思路有些变化，发生log file sync等待事件过高说明服务器IO出现瓶颈，这是没有问题的。如果此服务器IO一直没有问题，就今天出了问题，可能是SQL导致，接着分析Segments by Physical Reads，可以看到是查询那些表的无力度高。再通过这些表找到对应的SQL优化。

本次的优化就是优化SQL后，整个系统的物理读降下来了，log file sync也降到了5。

<table> 
 <tbody> 
  <tr> 
   <th><span style="background-color:rgb(153,153,255)">Host Name</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Platform</span></th> 
   <th><span style="background-color:rgb(153,153,255)">CPUs</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Cores</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Sockets</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Memory (GB)</span></th> 
  </tr> 
  <tr> 
   <td>gg-sjk-01</td> 
   <td>AIX-Based Systems (64-bit)</td> 
   <td align="right">128</td> 
   <td align="right">32</td> 
   <td align="right">&nbsp;</td> 
   <td align="right">240.00</td> 
  </tr> 
 </tbody> 
</table>

<table> 
 <tbody> 
  <tr> 
   <th><span style="background-color:rgb(153,153,255)"><br> </span></th> 
   <th><span style="background-color:rgb(153,153,255)">Snap Id</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Snap Time</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Sessions</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Cursors/Session</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Instances</span></th> 
  </tr> 
  <tr> 
   <td>Begin Snap:</td> 
   <td align="right">5446</td> 
   <td align="middle">25-Nov-15 15:00:42</td> 
   <td align="right">1084</td> 
   <td align="right">138.8</td> 
   <td align="right">2</td> 
  </tr> 
  <tr> 
   <td>End Snap:</td> 
   <td align="right">5447</td> 
   <td align="middle">25-Nov-15 16:00:11</td> 
   <td align="right">1086</td> 
   <td align="right">131.4</td> 
   <td align="right">2</td> 
  </tr> 
  <tr> 
   <td>Elapsed:</td> 
   <td>&nbsp;</td> 
   <td align="middle">59.49 (mins)</td> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
  </tr> 
  <tr> 
   <td>DB Time:</td> 
   <td>&nbsp;</td> 
   <td align="middle">6,185.41 (mins)</td> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
   <td>&nbsp;</td> 
  </tr> 
 </tbody> 
</table>

**Top 10 Foreground Events by Total Wait Time**

<table> 
 <tbody> 
  <tr> 
   <th><span style="background-color:rgb(153,153,255)">Event</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Waits</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Total Wait Time (sec)</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Wait Avg(ms)</span></th> 
   <th><span style="background-color:rgb(153,153,255)">% DB time</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Wait Class</span></th> 
  </tr> 
  <tr> 
   <td>enq: TX - row lock contention</td> 
   <td align="right">4,895</td> 
   <td align="right">88K</td> 
   <td align="right">17971</td> 
   <td align="right">23.7</td> 
   <td>Application</td> 
  </tr> 
  <tr> 
   <td>direct path read</td> 
   <td align="right">450,235</td> 
   <td align="right">59.7K</td> 
   <td align="right">133</td> 
   <td align="right">16.1</td> 
   <td>User I/O</td> 
  </tr> 
  <tr> 
   <td>gc buffer busy acquire</td> 
   <td align="right">996,236</td> 
   <td align="right">37.3K</td> 
   <td align="right">37</td> 
   <td align="right">10.0</td> 
   <td>Cluster</td> 
  </tr> 
  <tr> 
   <td>rdbms ipc reply</td> 
   <td align="right">82,075,609</td> 
   <td align="right">26.3K</td> 
   <td align="right">0</td> 
   <td align="right">7.1</td> 
   <td>Other</td> 
  </tr> 
  <tr> 
   <td>db file sequential read</td> 
   <td align="right">652,678</td> 
   <td align="right">22.8K</td> 
   <td align="right">35</td> 
   <td align="right">6.1</td> 
   <td>User I/O</td> 
  </tr> 
  <tr> 
   <td>db file scattered read</td> 
   <td align="right">828,115</td> 
   <td align="right">20.9K</td> 
   <td align="right">25</td> 
   <td align="right">5.6</td> 
   <td>User I/O</td> 
  </tr> 
  <tr> 
   <td>DB CPU</td> 
   <td align="right">&nbsp;</td> 
   <td align="right">20K</td> 
   <td align="right">&nbsp;</td> 
   <td align="right">5.4</td> 
   <td>&nbsp;</td> 
  </tr> 
  <tr> 
   <td>read by other session</td> 
   <td align="right">946,402</td> 
   <td align="right">18.5K</td> 
   <td align="right">20</td> 
   <td align="right">5.0</td> 
   <td>User I/O</td> 
  </tr> 
  <tr> 
   <td><span style="color:#ff0000"><strong>log file sync</strong></span></td> 
   <td align="right"><span style="color:#ff0000"><strong>103,436</strong></span></td> 
   <td align="right"><span style="color:#ff0000"><strong>16.3K</strong></span></td> 
   <td align="right"><span style="color:#ff0000"><strong>157</strong></span></td> 
   <td align="right"><span style="color:#ff0000"><strong>4.4</strong></span></td> 
   <td><span style="color:#ff0000"><strong>Commit</strong></span></td> 
  </tr> 
  <tr> 
   <td>gc cr block busy</td> 
   <td align="right">73,695</td> 
   <td align="right">13.1K</td> 
   <td align="right">178</td> 
   <td align="right">3.5</td> 
   <td>Cluster</td> 
  </tr> 
 </tbody> 
</table>

### Segments by Physical Reads ###

*  Total Physical Reads: 167,906,170
 *  Captured Segments account for 98.3% of Total

<table> 
 <tbody> 
  <tr> 
   <th><span style="background-color:rgb(153,153,255)">Owner</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Tablespace Name</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Object Name</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Subobject Name</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Obj. Type</span></th> 
   <th><span style="background-color:rgb(153,153,255)">Physical Reads</span></th> 
   <th><span style="background-color:rgb(153,153,255)">%Total</span></th> 
  </tr> 
  <tr> 
   <td>L_SYS</td> 
   <td>L_SYS_DATA</td> 
   <td>RU_DONE_TASK_MISS</td> 
   <td>&nbsp;</td> 
   <td>TABLE</td> 
   <td align="right">71,893,921</td> 
   <td align="right">42.82</td> 
  </tr> 
  <tr> 
   <td>L_SYS</td> 
   <td>L_SYS_DATA</td> 
   <td>USER_VISIT</td> 
   <td>&nbsp;</td> 
   <td>TABLE</td> 
   <td align="right">36,013,367</td> 
   <td align="right">21.45</td> 
  </tr> 
  <tr> 
   <td>L_SYS</td> 
   <td>L_SYS_DATA</td> 
   <td>RU_DONE_TASK_MRTN</td> 
   <td>&nbsp;</td> 
   <td>TABLE</td> 
   <td align="right">25,627,235</td> 
   <td align="right">15.26</td> 
  </tr> 
  <tr> 
   <td>L_Z</td> 
   <td>L_Z_DATA</td> 
   <td>PURCHASE_ITEM_MV</td> 
   <td>&nbsp;</td> 
   <td>TABLE</td> 
   <td align="right">16,697,719</td> 
   <td align="right">9.94</td> 
  </tr> 
  <tr> 
   <td>L_Z</td> 
   <td>L_Z_DATA</td> 
   <td>OPERATION_HISTORY</td> 
   <td>&nbsp;</td> 
   <td>TABLE</td> 
   <td align="right">12,571,365</td> 
   <td align="right">7.49</td> 
  </tr> 
 </tbody> 
</table>