Debug Diagnostic Tool

Oggi vedremo un caso di utilizzo del Debug Diagnostic Tool che è uno strumento molto utile per fare del debugging e del profiling sia in ambiente di Sviluppo ma sopratutto in ambiente di Produzione.

Il caso in particolare è andare ad analizzare una applicaizone ASP che in produzione, sotto stress quindi, ogni tanto manda il processore del server al 100%.

Come primo workaround si è subito messo in linea uno script di Power Shell che andasse a verificare lo stato del processore e nel caso fosse rimasto al 95% per più di 20sec, andasse a fare un IIS Reset.

Poi subito dopo seguendo questo articolo su Debuggin IIS High CPU siamo andati a impostare:

  1. Data Collection con il Performance Monitor
    In particolar modo:

    • Richieste Correnti Totali (ASP .NET)
    • Richieste in Coda (ASP .NET)
  2. Creazione di un Dump tramite Debug Diagnostic Tool 2 Collection
    In particolare:

    • Se il processore rimaneva al 90% per più di 5 secondi

E siamo rimasti ad aspettare che nuovamente succedesse lo scenario incriminato.

Abbiamo lasciato in piedi la cosa per tutta la notte: il data collection continua finchè non lo si stoppa, mentre il dump è one-time (una volta scattato, va riattivato manualmente il trigger, altrimenti si ferma).

Nella notte abbiamo avuto ben 4 casi di processore al 100% e durante il primo caso si è generato il Dump e durante tutti i casi abbiamo collezionato i dati dei contatori per le Richieste Correnti e per le richieste in Coda.

Ecco come abbiamo poi analizzato la cosa.

Per quanto riguarda i dati collezionati dal Performance Monitor si è visto che le richieste correnti schizzavano in occorrenza dell’evento incriminato:

Andando ad analizzare anche le richieste in coda:

si evince che aumentano proporzionalmente alle richieste attive.

Questo ci fa sospettare che sia effettivamente un problema di performance e non un problema di “attacco” in quanto le richieste in coda ci sono solamente durante gli eventi incriminati e quindi IIS non riesce ad evadere le richieste perchè è impegnato nell’operazione che porta il processore al 100% e questo scenario è coerente con il fatto che facendo IIS Reset la situazione ritorno normale.

Andiamo quindi ora ad analizzare il dump con il Debug Diagnosti Tool 2 Analysis.

Vediamo subito che l’analisi del Dump conferma High CPU Usage.

Andando a vedere quindi i Topo 8 Thread scopriamo da dove parte il tutto:

Dalla pagina “RivestimentiDettagli” ed è scatenata dal metodo “.get_data()” (Tutto Codice Utente).

Andando quindi ad analizzare il codice si è scoperto che si era fatto un uso improprio di variabili statiche e quindi c’erano problemi di concorrenza che si vedevano solo in presenza di forte carico del server.

 

 

 

Debug Diagnostic Tool

Debugging .NET application con WinDbg

E’ possibile creare un file minidump anche per applicazioni .NET nello stesso modo descritto nell’articolo per le applicaizoni native:

http://www.versionestabile.it/blog/dubugging-with-windbg/

Per le applicazioni .NET è più difficile avere la riga di codice esatta, soprattutto se non si è tenuto il file .pdb della versione che ha fatto il “crash” a casa del cliente e non vengono caricati correttamente anche i symboli delle classi .NET relative al Framework con cui è stato compilato il programma in question.

Per prima cosa lanciare il caricamento del framework

.loadby sos clr

Comunque anche se si dispone solo del file .dump (vedere come generarlo nell’articolo citato sopra) se lo si apre con WinDBG e si analizzano al suo interno le eccezioni con il comando

!analyze -v

Si può vedere lo stack trace che ci porta al punto di programma incriminato.

Vediamo un esempio.

Il programma C# del nostro esempio è il seguente:

using System;
using System.Collections.Generic;
using System.ComponentModel;
using System.Data;
using System.Drawing;
using System.Linq;
using System.Text;
using System.Windows.Forms;

namespace WinDbgCrashTest
{
    public partial class Form1 : Form
    {
        public Form1()
        {
            InitializeComponent();
            badMethod();
        }

        private void badMethod() {
            Object o = null;
            String s = o.ToString();
        }
    }
}

Se lo si lancia andrà in Crash immediato.

Apriamo il suo minidump con WinDBG e lanciamo !analyze -v

Lancirare WinDbg come amministratore in modo che possa scaricare (dal sito di Microsoft) nelle cartelle di sistema i simboli che eventualmente non trova in locale.

Ecco il risultato:

windbg_net_crash1
Anche se non è riuscito a caricare i simboli

crash_net_windbg_0
ci dice che alla riga 2 del metodo badMethod all’interno della classe Form1 si è verificata l’eccezione!

Se diamo a WinDBG il path del .pdb e dei sorgenti che fanno riferimento a quell’eseguibile con il comando

!clrstack

Abbiamo anche più info: il file e la riga dove è avvenuta l’eccezione.
crash_net_windbg

Debugging .NET application con WinDbg

Creare un webservice a partire dal suo wsdl

Vi hanno chiesto di fare un Web Service che rispetti una certa interfaccia wsdl e vi hanno dato solo il file .wsdl?

Niente paura, partite da qui:

1. Aprite il command prompt di visual studio

2. Andate nella directory che contiene il vostro file .wsdl chiamiamolo webservice.wsdl

3. Eseguite il comando

wsdl.exe webservice.wsdl /l:CS /serverInterface

dove /l da il linguaggio da utilizzare (CS=C#, VB=Visual Basic).

Verrà generato il vile .cs da importare nel vostro progetto WebService.

Non dovrete fare altro che andare a dire alla classe del vostro WebService di implementare tale interfaccia.

Buon lavoro!

Creare un webservice a partire dal suo wsdl

C# virtual method

Cosa significa dichiarare un methodo “virtual”?

Se un metodo virtuale viene invocato è il tipo di classe a run-time che determina quale metodo verrà invocato.

In un metodo non virutale è, al contrario, il tipo di classe a compile-time che determina quale metodo verrà invocato.

Ad esempio se abbiamo una classe padre come la seguente

namespace VirtaulMethodExamples
{
    public class Father
    {
        public virtual string getVirtaulName() {
            return "Father.getVirtaulName()";
        }

        public string getName() {
            return "Father.getName()";
        }
    }
}

e una classe figlia da essa derivata

namespace VirtaulMethodExamples
{
    public class Child: Father
    {
        public override string getVirtaulName()
        {
            return "Child.getVirtaulName()";
        }

        public new string getName()
        {
            return "Child.getName()";
        }
    }
}

Nel seguente schenario

Child child = new Child();
Father father = child;

Console.WriteLine(child.getVirtaulName());
Console.WriteLine(child.getName());
Console.WriteLine(father.getVirtaulName());
Console.WriteLine(father.getName());

verrà scritto a console

Child.getVirtaulName()
Child.getName()
Child.getVirtaulName()
Father.getName()

La penultima riga richiamando un metodo virtual guardal al tipo di classe a run-time (Child) e non al tipo di classe a compile-time (Father) per invocare il metodo.

Contrariamente, l’ultima riga guarda al tipo di classe a compile-time (Father) per invocare il metodo non virtual.

Da notare l’uso della parola chiave “new” nella dichiarazione del metodo getName() nella classe Child per non avere un warning di compilazione in quanto il metodo getName di Child nasconde il metodo getName di Father.

C# virtual method

Logging Framework: log4net

Il Log è una parte importante di molti programmi.
Esiste un Framework molto valido, dal lontano 1996 su linguaggio Java, che permette in sintesi:
  • Logging su più canali
  • Gerarchie di log
  • Filtri
  • Configurabile da file (con watcher)
Il sito ufficiale è: http://logging.apache.org/log4net/
Ecco un esempio di log4net.config file:

<!-- This section contains the log4net configuration settings -->
<log4net>
   <!-- File Appender -->
   <appender name="LogFileAppender" type="log4net.Appender.FileAppender">
      <file value="log-file.txt" />
      <sppendToFile value="true" />
      <layout type="log4net.Layout.PatternLayout">
         <header value="[Header]&#xD;&#xA;" />
         <footer value="[Footer]&#xD;&#xA;" />
         <conversionPattern value="%date [%thread] %-5level %logger (%property{log4net:HostName}) [%ndc] - %message%newline" />
      </layout>
   </appender>
   <!-- Rolling File! 🙂 -->
   <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="example.log" />
      <appendToFile value="true" />
      <maximumFileSize value="100KB" />
      <maxSizeRollBackups value="2" />
      <layout type="log4net.Layout.PatternLayout">
         <conversionPattern value="%level %thread %logger - %message%newline" />
      </layout>
   </appender>
   <!-- Console Appender -->
   <!-- appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender" >
 <layout type="log4net.Layout.PatternLayout">
 <conversionPattern value="%date [%thread] %-5level %logger [%ndc] - %message%newline" />
 </layout>
 </appender -->
   <!-- EventID Appender -->
   <!--
 Also note that if your program is called app.exe, then you need an eventlog source called app.exe.
 If this does not exist, then Log4net will attempt to create it, but that requires Admin rights, 
 so you may need to run your program as admin at least once in order to create this event source. 
 To avoid this, the event source would normally be created as part of the installation procedure which 
 would already be running as admin.
 -->
   <appender name="EventLogAppender" type="log4net.Appender.EventLogAppender">
      <!--applicationName value="log4net_lab" /-->
      <layout type="log4net.Layout.PatternLayout">
         <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
   </appender>
   <!-- Database Appender -->
   <!-- Example of how to configure the AdoNetAppender to connect to MS SQL Server -->
   <appender name="ADONetAppender_SqlServer" type="log4net.Appender.AdoNetAppender">
      <bufferSize value="1" />
      <connectionType value="System.Data.SqlClient.SqlConnection, System.Data, Version=1.0.3300.0, Culture=neutral, PublicKeyToken=b77a5c561934e089" />
      <connectionString value="data source=your_host catalog=your_database;integrated security=false;persist security info=True;User ID=your_user;Password=your_password" />
      <commandText value="INSERT INTO Log ([Date],[Thread],[Level],[Logger],[Message]) VALUES (@log_date, @thread, @log_level, @logger, @message)" />
      <parameter>
         <parameterName value="@log_date" />
         <dbType value="DateTime" />
         <!-- 
 <layout type="log4net.Layout.PatternLayout">
 <conversionPattern value="%date{yyyy'-'MM'-'dd HH':'mm':'ss'.'fff}" />
 </layout> 
 -->
         <layout type="log4net.Layout.RawTimeStampLayout" />
      </parameter>
      <parameter>
         <parameterName value="@thread" />
         <dbType value="String" />
         <size value="255" />
         <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%thread" />
         </layout>
      </parameter>
      <parameter>
         <parameterName value="@log_level" />
         <dbType value="String" />
         <size value="50" />
         <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%level" />
         </layout>
      </parameter>
      <parameter>
         <parameterName value="@logger" />
         <dbType value="String" />
         <size value="255" />
         <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%logger" />
         </layout>
      </parameter>
      <parameter>
         <parameterName value="@message" />
         <dbType value="String" />
         <size value="4000" />
         <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%message" />
         </layout>
      </parameter>
   </appender>
   <!-- SQLite Appender -->
   <appender name="AdoNetAppender_SQLite" type="log4net.Appender.AdoNetAppender">
      <bufferSize value="100" />
      <connectionType value="System.Data.SQLite.SQLiteConnection, System.Data.SQLite, Version=1.0.96.0, Culture=neutral, PublicKeyToken=db937bc2d44ff139" />
      <connectionString value="Data Source=log4net.db3;Version=3;" />
      <commandText value="INSERT INTO Log (Date, Level, Logger, Message) VALUES (@Date, @Level, @Logger, @Message)" />
      <parameter>
         <parameterName value="@Date" />
         <dbType value="DateTime" />
         <layout type="log4net.Layout.RawTimeStampLayout" />
      </parameter>
      <parameter>
         <parameterName value="@Level" />
         <dbType value="String" />
         <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%level" />
         </layout>
      </parameter>
      <parameter>
         <parameterName value="@Logger" />
         <dbType value="String" />
         <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%logger" />
         </layout>
      </parameter>
      <parameter>
         <parameterName value="@Message" />
         <dbType value="String" />
         <layout type="log4net.Layout.PatternLayout">
            <conversionPattern value="%message" />
         </layout>
      </parameter>
   </appender>
   <!-- Assign Appenders -->
   <root>
      <level value="DEBUG" />
      <!--level value="All"/-->
      <appender-ref ref="LogFileAppender" />
      <appender-ref ref="RollingFileAppender" />
      <!--appender-ref ref="ConsoleAppender"/-->
      <appender-ref ref="EventLogAppender" />
      <!--appender-ref ref="ADONetAppender_SqlServer"/-->
      <appender-ref ref="AdoNetAppender_SQLite" />
   </root>
   <!-- Print only messages of level WARN or above in the package Com.Foo -->
   <logger name="Com.Foo">
      <level value="WARN" />
   </logger>
</log4net>
Logging Framework: log4net