DTrace

From GridWiki
(Redirected from Dtrace)
Jump to: navigation, search

DTrace-based Master monitoring under Solaris 10

Copyright statement

Note: This document is under Grid Engine project SISSL license.

Introduction

Trouble-shooting in a distributed system spanning multiple thousands active components like Grid Engine can become a real challenge. In practice Grid Engine administrators have no a priori certainty about reasons for performance degradation in their production environments and reproducing such problems is not easy for those who wish to help. For that reason it is important to have a utility for on-site performance monitoring of the Grid Engine master component. Thanks to DTrace(1) support in Solaris 10 a platform exists that is suited even for monitoring of multi-threaded/multi-processing components like Grid Engine master (=qmaster scheduler) :)

Project Overview

Project Aim

Aim is to provide an easy-to-use DTrace-based bottleneck analysis first-aid kit to Grid Engine administrators. Though with this utility it will not be possible to entirely understand any single case where performance degregation occurs. However in a majority of cases it will provide sufficient insight required by administrator to independently find an appropriate remedy. In other cases it shall deliver a base that facilitates more experienced people to help in a determined and time-saving way.

Project Benefit

Grid Engine administrators will be able to independently tune their Grid Engine clusters and can get faster and better help from those who made comparable experiences in other challenging cases.

Block diagram

Imagine one of these nice block diagrams pictures. Components apparently are

  • Grid Engine master
  • DTrace master monitor (D scripts)
  • dtrace(1M) command
  • Solaris 10

Performance Impact

There is no performance impact to Grid Engine when DTrace is not enabled. When DTrace is enabled, the overhead is negligible because DTrace does not stop and restart the qmaster for each traced function. Instead, DTrace collects data in per-CPU buffers which dtrace(1M) asynchronously reads. (ref 1)

Packaging

Master monitor will be part of the 'common' package in $SGE_ROOT/dtrace directory.

Implementation

The master monitor soley depends on DTrace pid provider probes. These probes are used to track calls to throughput-sensitive functions in qmaster/scheduler. Note, for the DTrace pid provider based monitor to function it is required these functions are not inlined as explained in DTrace documentation CR #6480235.

The list of the functions tracked by the monitor is:

  • cl_message_list_append_receive()
  • cl_message_list_append_send()
  • cl_message_list_remove_receive()
  • cl_message_list_remove_send()
  • dispatch_jobs()
  • do_c_ack()
  • do_gdi_packet()
  • report_list_send()
  • select_assign_debit()
  • sge_c_gdi_add()
  • sge_c_gdi_copy()
  • sge_c_gdi_del()
  • sge_c_gdi_get()
  • sge_c_gdi_mod()
  • sge_c_gdi_permcheck()
  • sge_c_gdi_trigger()
  • sge_c_report()
  • sge_lock()
  • sge_log()
  • sge_mirror_process_events()
  • sge_unlock()
  • spool_delete_object()
  • spool_write_object()
  • spool_read_object()
  • spool_delete_script()
  • spool_write_script()
  • spool_read_script()

Appendix

Example #1

The following monitoring output sample illustrates a case where a Grid Engine master bottleneck could be detected. With the at hand sample performance degregation happend between 17:40:32 and 17:41:05.

CPU     ID                    FUNCTION:NAME
  0      1                           :BEGIN                 Time |   #wrt  wrt/ms |#rep #gdi #ack|   #dsp  dsp/ms    #sad|   #snd    #rcv|  #in     #in--  #out    #out--|  #lck0  #ulck0   #lck1  #ulck1
  0  36909                       :tick-3sec 2006 Nov 24 17:39:23 |      43       3|   0    8    4|      3     691     121|      4       4|     11      11      15      15|     68      68     289     288
  0  36909                       :tick-3sec 2006 Nov 24 17:39:26 |      83      16|   0   10    3|      3     699     122|      3       3|     14      13      17      17|     90      90     681     681
  0  36909                       :tick-3sec 2006 Nov 24 17:39:29 |     117      24|   0    9    4|      4    1092     198|      4       4|     13      13      17      17|     71      71     591     591
  0  36909                       :tick-3sec 2006 Nov 24 17:39:32 |      19       4|   0    9    3|      3     591     147|      3       3|     12      12      15      15|     44      43     249     249
  0  36909                       :tick-3sec 2006 Nov 24 17:39:35 |     144      28|   0    9    4|      4    1012     173|      4       4|     13      13      17      17|     61      62    1246    1247
  0  36909                       :tick-3sec 2006 Nov 24 17:39:38 |      46       5|   0    8    3|      3     705     122|      3       3|     11      11      14      14|     67      67     293     293
  0  36909                       :tick-3sec 2006 Nov 24 17:39:41 |     154      31|   0    9    3|      4     894     198|      3       3|     13      13      16      16|     73      72     968     969
  0  36909                       :tick-3sec 2006 Nov 24 17:39:44 |      46       5|   0   10    4|      4     971     162|      4       4|     13      13      17      17|     71      72     304     304
  0  36909                       :tick-3sec 2006 Nov 24 17:39:47 |     154      29|   0    8    3|      3     739     158|      3       3|     11      11      14      14|     67      67     990     990
  0  36909                       :tick-3sec 2006 Nov 24 17:39:50 |      46       5|   0   10    4|      4     815     162|      4       4|     14      14      18      18|     76      76     692     693
  0  36909                       :tick-3sec 2006 Nov 24 17:39:53 |      74      15|   0    8    3|      3     746     136|      3       3|     12      12      15      15|     54      53     571     571
  0  36909                       :tick-3sec 2006 Nov 24 17:39:56 |     116      20|   0   11    4|      4     992     184|      4       4|     14      14      18      18|     80      81     669     669
  0  36909                       :tick-3sec 2006 Nov 24 17:39:59 |      87      18|   0   11    4|      4     851     176|      5       4|     15      15      21      21|     77      76     670     670
  0  36909                       :tick-3sec 2006 Nov 24 17:40:02 |     109      20|   0   12    5|      4     930     184|      4       5|     17      17      20      20|     77      78     624     624
  0  36909                       :tick-3sec 2006 Nov 24 17:40:05 |      88      15|   0    9    3|      4     995     176|      3       3|     12      12      15      15|     71      71    1026    1026
  0  36909                       :tick-3sec 2006 Nov 24 17:40:08 |     112      20|   0   12    4|      4     927     184|      5       4|     16      16      22      22|     81      81     652     652
  0  36909                       :tick-3sec 2006 Nov 24 17:40:11 |      32       6|   0    7    4|      3     618     121|      3       4|     11      11      13      13|     54      53     336     336
  0  36909                       :tick-3sec 2006 Nov 24 17:40:14 |     145      30|   0   11    4|      4     988     199|      4       4|     15      15      19      19|     64      65     827     827
  0  36909                       :tick-3sec 2006 Nov 24 17:40:17 |      43       3|   0    7    3|      3     618     121|      3       3|     10      10      13      13|     64      64     286     286
  0  36909                       :tick-3sec 2006 Nov 24 17:40:20 |     157      31|   0   11    4|      4     977     199|      4       4|     15      15      19      19|     80      80    1406    1408
  0  36909                       :tick-3sec 2006 Nov 24 17:40:23 |      43       4|   0    7    3|      3     701     121|      3       3|     10      10      13      13|     64      64     285     285
  0  36909                       :tick-3sec 2006 Nov 24 17:40:26 |      73      18|   0   11    4|      4     948     171|      4       4|     15      15      19      19|     77      77     700     700
  0  36909                       :tick-3sec 2006 Nov 24 17:40:29 |     127      31|   0   10    4|      4     968     189|      4       4|     14      14      18      18|     74      74     584     584
  0  36909                       :tick-3sec 2006 Nov 24 17:40:32 |      10       3|   0    6    0|      1     203      41|      0       0|     58       8      62      62|     23      22     106     106
  0  36909                       :tick-3sec 2006 Nov 24 17:40:35 |      19       5|   0    5    0|      0       0       0|      0       0|      8       5      13      13|     30      30     200     200
  0  36909                       :tick-3sec 2006 Nov 24 17:40:38 |      16       5|   0    5    1|      0       0       0|      0       0|      5       6      10      10|     27      26     558     559
  0  36909                       :tick-3sec 2006 Nov 24 17:40:41 |       1       0|   0    4    0|      0       0       0|      0       0|      7       4      11      11|      9       9      34      34
  0  36909                       :tick-3sec 2006 Nov 24 17:40:44 |       0       0|   0    4    0|      0       0       0|      0       0|      7       4      11      11|      8       8      28      28
  0  36909                       :tick-3sec 2006 Nov 24 17:40:47 |       0       0|   0    6    0|      1     744      81|      1       1|     10       6      15      15|     14      14      33      33
  0  36909                       :tick-3sec 2006 Nov 24 17:40:50 |       1       0|   0    5    1|      0       0       0|      0       0|      8       6      14      14|     11      11      49      49
  0  36909                       :tick-3sec 2006 Nov 24 17:40:53 |       0       0|   0    4    0|      0       0       0|      0       0|      9       4      12      12|      6       7      28      28
  0  36909                       :tick-3sec 2006 Nov 24 17:40:56 |       0       0|   0    5    0|      0       0       0|      0       0|      8       5      13      13|     12      12     420     420
  0  36909                       :tick-3sec 2006 Nov 24 17:40:59 |       0       0|   0    4    0|      0       0       0|      0       0|      8       4      12      12|      9       8      30      30
  0  36909                       :tick-3sec 2006 Nov 24 17:41:02 |       0       0|   0    4    1|      0       0       0|      0       0|     12       5      16      16|      7       8      25      25
  0  36909                       :tick-3sec 2006 Nov 24 17:41:05 |     165      41|   0   48   60|      0       0       0|      1       1|     23     106      71      71|     96      97    1236    1236
  0  36909                       :tick-3sec 2006 Nov 24 17:41:08 |     178      28|   0   15   53|      4     965     206|      4       4|     68      68      75      75|    130     130    1336    1336
  0  36909                       :tick-3sec 2006 Nov 24 17:41:11 |     106      23|   0   27   35|      4     855     166|      4       4|     82      82      91      91|    115     114    1040    1040
  0  36909                       :tick-3sec 2006 Nov 24 17:41:14 |     198      37|   0   41   70|      4    1189     196|      4       4|    185     185     185     185|    134     135    1327    1327
  0  36909                       :tick-3sec 2006 Nov 24 17:41:17 |      16       5|   0    9    5|      4     940     161|      3       3|     17      17      20      20|     43      42     234     234
  0  36909                       :tick-3sec 2006 Nov 24 17:41:20 |     162      35|   0   13    8|      4     958     200|      4       4|     23      23      28      28|     80      81    1018    1018
  0  36909                       :tick-3sec 2006 Nov 24 17:41:23 |      44       6|   0    6    3|      2     544      81|      3       3|      8       8      11      11|     63      63     747     747
  0  36909                       :tick-3sec 2006 Nov 24 17:41:26 |     150      34|   0   13    6|      4     921     199|      4       4|     21      21      25      25|     73      72     923     923
  0  36909                       :tick-3sec 2006 Nov 24 17:41:29 |      43       3|   0    5    2|      2     506      81|      2       2|      7       7       9       9|     57      57     260     260
  0  36909                       :tick-3sec 2006 Nov 24 17:41:32 |     157      37|   0    9    3|      4     978     199|      3       3|     13      13      16      16|     73      72     970     970
  0  36909                       :tick-3sec 2006 Nov 24 17:41:35 |      43       3|   0    7    3|      2     512      85|      3       3|      9       9      12      12|     61      62     274     274
  0  36909                       :tick-3sec 2006 Nov 24 17:41:38 |     127      29|   0    8    3|      4     994     185|      3       3|     11      11      14      14|     68      68    1265    1265
  0  36909                       :tick-3sec 2006 Nov 24 17:41:41 |      66      11|   0   10    4|      4     973     171|      4       4|     14      14      18      18|     67      67     354     354
  0  36909                       :tick-3sec 2006 Nov 24 17:41:44 |      48      10|   0    8    3|      3     785     128|      3       3|     11      11      14      14|     52      51     399     399
  0  36909                       :tick-3sec 2006 Nov 24 17:41:47 |     142      31|   0   12    4|      4     913     192|      5       4|     17      17      23      23|     89      90     830     830
  0  36909                       :tick-3sec 2006 Nov 24 17:41:50 |      64      13|   0   11    5|      4     853     168|      4       5|     15      15      18      18|     75      75     542     542

cause for the performance decline were a couple of dozens 'qsub -sync y' as explained in qmaster performance gets throttled if qsub -sync y is used when many jobs are in the system

Example #2

This case shows how the 6.0u8 based DTrace script (SGE60-dtrace.tar.gz) helped to understand the cause of sporadic 'qmaster alive timeout expiring' loggings

                Time |    #wrt  wrt/ms|#rep #gdi #ack|   #dsp  dsp/ms    #sad|   #snd    #rcv|  #lck0  #ulck0   #lck1  #ulck1
2006 Oct 21 04:04:52 |      80    2020|  77   30   15|     15     810      30|     15      15|    199     199    1660    1660
2006 Oct 21 04:05:07 |     101    2563|  76   30   15|     15     808      36|     15      15|    197     197    1701    1702
2006 Oct 21 04:05:22 |     130    3502| 100   31   15|     15     818      40|     15      15|    232     232    2028    2027
2006 Oct 21 04:05:37 |     161    4798| 103   30   15|     15     804      47|     15      15|    224     224    2050    2050
2006 Oct 21 04:05:52 |     169    4926| 108   30   15|     15     818      50|     15      15|    230     230    2133    2136
2006 Oct 21 04:06:07 |     134    3809|  98   30   15|     15     801      41|     15      15|    219     219    1942    1942
2006 Oct 21 04:06:22 |     192    5838| 113   31   15|     15     836      53|     15      15|    245     245    2172    2170
2006 Oct 21 04:06:37 |     346   13390| 185   27   13|     14     828      89|     13      13|    296     295    3064    3063
2006 Oct 21 04:06:52 |     364   13975| 178   13    6|      7     449      80|      7       7|    231     231    2879    2879
2006 Oct 21 04:07:07 |     355   14263| 182    7    4|      3     243      72|      3       3|    212     212    2991    2992
2006 Oct 21 04:07:22 |     335   14190| 179    5    2|      2     187      70|      2       2|    207     207    2857    2858
2006 Oct 21 04:07:37 |     297   14203| 178    3    1|      2     206      90|      2       2|    190     190    2639    2641
2006 Oct 21 04:07:52 |     383   13728| 133    4    2|      3     419     219|      2       3|    153     153    2442    2442
2006 Oct 21 04:08:07 |     432   13680| 115    3    1|      2     328     190|      1       2|    126     126    1930    1931
2006 Oct 21 04:08:22 |     498   13451| 226    6    2|      2     281     142|      3       2|    251     251    3086    3085
2006 Oct 21 04:08:37 |     411   13331|  89    4    2|      2     422     245|      2       2|    114     114    1938    1939
2006 Oct 21 04:08:52 |     473   13595| 136    3    1|      2     420     264|      1       2|    147     147    2194    2193
2006 Oct 21 04:08:57 | sge_log(4, qmaster alive timeout expired)
2006 Oct 21 04:09:07 |     322   11950|  85    3    1|      0       0       0|      2       1|    100     100    1561    1561
2006 Oct 21 04:09:22 |     512    9825| 291    9    1|      1     356     215|      2       1|    325     325    3850    3849
2006 Oct 21 04:09:37 |     226   14398|   0    0    0|      1     353     215|      0       1|      0       0     843     843
2006 Oct 21 04:09:40 | sge_log(4, qmaster alive timeout expired)
2006 Oct 21 04:09:52 |     200   13072|  30    1    0|      0       0       0|      1       1|     35      35    1301    1301
2006 Oct 21 04:10:07 |     516   11657| 139    2    0|      0       0       0|      1       0|    148     148    1900    1900
2006 Oct 21 04:10:22 |     302    9965| 434    3    0|      0       0       0|      0       0|    449     450    4439    4441
2006 Oct 21 04:10:37 |     404   12147|  10    5    1|      2     759     456|      1       2|     26      25    1214    1214
2006 Oct 21 04:10:44 | sge_log(4, qmaster alive timeout expired)
2006 Oct 21 04:10:52 |     225   14003|   0    0    0|      0       0       0|      0       1|      0       0     834     834
2006 Oct 21 04:11:07 |     381   12033| 120    1    0|      0       0       0|      1       0|    127     127    1733    1733
2006 Oct 21 04:11:22 |     502   12540| 338    2    0|      0       0       0|      1       0|    346     346    3492    3493
2006 Oct 21 04:11:37 |     434   12547| 151    7    1|      2     708     422|      1       2|    179     179    2964    2963
2006 Oct 21 04:11:47 | sge_log(4, qmaster alive timeout expired)
2006 Oct 21 04:11:52 |     187   14300|   0    0    0|      0       0       0|      0       1|      0       0     706     706
2006 Oct 21 04:12:07 |     378   12619|  93    1    0|      0       0       0|      1       0|    100     100    1483    1483
2006 Oct 21 04:12:22 |     474   13377| 357    2    0|      0       0       0|      1       0|    365     365    3897    3897
2006 Oct 21 04:12:37 |     384    8363| 154    8    1|      1     371     220|      1       1|    184     184    2809    2809
2006 Oct 21 04:12:52 |     203   14475|   0    0    0|      1     376     220|      0       1|      0       0     770     770
2006 Oct 21 04:12:52 | sge_log(4, qmaster alive timeout expired)
2006 Oct 21 04:13:07 |     234   13167|  98    1    0|      0       0       0|      1       1|    105     105    1556    1556
2006 Oct 21 04:13:22 |     430   11001|  21    1    0|      0       0       0|      0       0|     24      24    1080    1080
2006 Oct 21 04:13:37 |     332   14139| 387    1    0|      0       0       0|      1       0|    394     394    4101    4101
2006 Oct 21 04:13:52 |     420   12256| 141    8    1|      2     820     488|      1       2|    169     169    2227    2227
2006 Oct 21 04:14:03 | sge_log(4, qmaster alive timeout expired)
2006 Oct 21 04:14:07 |     212   14377|   0    0    0|      0       0       0|      0       1|      0       0     788     788
2006 Oct 21 04:14:22 |     274   12997|  86    1    0|      0       0       0|      1       0|     93      93    1537    1537
2006 Oct 21 04:14:37 |     376   11234|  23    1    0|      0       0       0|      0       0|     26      26    1020    1020
2006 Oct 21 04:14:52 |     273   14371| 325    1    0|      0       0       0|      1       0|    332     332    3274    3274

here inadequately set-up spooling (classic over NFS) caused that qmaster was almost entirely busy with IO. This can be concluded from the interval being 15 seconds with 'wrt/ms' being up to 14.475 seconds. The qmaster alive timeout was a side implication. The bug is described under qmaster logging "scheduler tried to remove a incomplete"

Troubleshooting

Problems under Solaris10U2

It was reported the master monitor couldn't be started under Solaris10U2, but that could be fixed by applying the most recent patch cluster.

Reference

See also