dimanche 28 septembre 2014

SqlCommand.ExecuteReader et lecture partielle du jeu de résultats


Vous pensez qu'en ne lisant qu'un seul enregistrement sur une instance de SqlDataReader retournée par ExecuteReader vous n'allez pas provoquer le transfert sur le réseau de l'ensemble du jeu de résultats ?
Faux :-)
Mais la bonne nouvelle c'est que c'est en partie corrigeable.

La question de la lecture partielle du jeu de résultats d'une requête ne se pose généralement pas : il est toujours préférable d'utiliser des requêtes ne retournant que les données nécessaires.
Cependant l'arrêt de la lecture d'un jeu de résultats avant d'en avoir atteint la fin peut se justifier, comme par exemple dans le cas de l'arrêt d'un traitement pour cause de dépassement de délai : il n'y a aucun intérêt à finir de lire les données pour un traitement dont le résultat ne sera pas utilisé.
Si dans ce cas vous vous contentez de sortir de la boucle de lecture des enregistrements, vous avez un problème.

Contexte technique de rédaction de ce post : .NET 4.5 et SQL Server 2014 Express (mais de mémoire c'est comme ça depuis minimum .NET 2.0).
Source de données utilisée : table Person.Person de la base d'exemple Adventure Works 2014 (Adventure Works 2014 Full Database Backup.zip) du 25/07/2014, environ 19000 enregistrements pour un total de plus de 20 Mo.




Le problème

Utilisé avec une requête du type "SELECT * FROM [Person].[Person]" le code d'accès aux données suivant, tout à fait standard mais simplifié pour améliorer la lisibilité, entrainera un transfert complet des données malgré le fait qu'il ne fasse qu'un seul appel à Read :

using (SqlConnection connection = new SqlConnection(connectionString))
{
    connection.Open();
    using (SqlCommand command = new SqlCommand(commandText, connection))
    {
        command.CommandType = CommandType.Text;
        command.CommandTimeout = 10 * 60;
        using (SqlDataReader reader = command.ExecuteReader())
        {
            reader.Read();
            Object result = reader.GetValue(0);
        }
    }
}


Ce n'est pas forcément le comportement auquel on s'attend de la part d'une API de ce type.




Creusons un peu

Instrumentons un peu le code pour relever les temps d'exécution et les volumes de données transférés en divers points du code (grâce au mécanisme de statistiques disponible depuis ADO.NET 2.0 qui sera suffisant dans le cas présent) :

Stopwatch timing = Stopwatch.StartNew();
using (SqlConnection connection = new SqlConnection(connectionString))
{
    connection.StatisticsEnabled = true;
    connection.Open();

    using (SqlCommand command = new SqlCommand(commandText, connection))
    {
        command.CommandType = CommandType.Text;
        command.CommandTimeout = 10 * 60;

        PrintTimingAndStatistics("ExecuteReader (before)", timing, connection.RetrieveStatistics());
        using (SqlDataReader reader = command.ExecuteReader())
        {
            PrintTimingAndStatistics("ExecuteReader (after)", timing, connection.RetrieveStatistics());
            PrintTimingAndStatistics("Read (before)", timing, connection.RetrieveStatistics());
            reader.Read();
            PrintTimingAndStatistics("Read (after)", timing, connection.RetrieveStatistics());
            PrintTimingAndStatistics("GetValue (before)", timing, connection.RetrieveStatistics());
            Object result = reader.GetValue(0);
            PrintTimingAndStatistics("GetValue (after)", timing, connection.RetrieveStatistics());
            PrintTimingAndStatistics("SqlDataReader.Close (before)", timing, connection.RetrieveStatistics());
            reader.Close();
            PrintTimingAndStatistics("SqlDataReader.Close (after)", timing, connection.RetrieveStatistics());
            PrintTimingAndStatistics("SqlDataReader cleanup (before)", timing, connection.RetrieveStatistics());
        }
        PrintTimingAndStatistics("SqlDataReader cleanup (after)", timing, connection.RetrieveStatistics());
        PrintTimingAndStatistics("SqlCommand cleanup (before)", timing, connection.RetrieveStatistics());  
    }
    PrintTimingAndStatistics("SqlCommand cleanup (after)", timing, connection.RetrieveStatistics());
    PrintTimingAndStatistics("SqlConnection.Close (before)", timing, connection.RetrieveStatistics());
    connection.Close();
    PrintTimingAndStatistics("SqlConnection.Close (after)", timing, connection.RetrieveStatistics());
}



private static void PrintTimingAndStatistics(String label, Stopwatch timing, IDictionary connectionStatistics)
{
    Console.WriteLine("{0} : {1} : {2} rows / {3} bytes / {4} buffers", 
        timing.Elapsed,
        label, 
        connectionStatistics["SelectRows"],
        connectionStatistics["BytesReceived"],
        connectionStatistics["BuffersReceived"]
        );
}

J'ai aussi ajouté des appels explicites à SqlDataReader.Close et SqlConnection.Close afin de prendre des mesures autour de leur exécution seule, hors du contexte de la méthode Dispose à qui cet appel était délégué dans mon premier exemple.


A titre de comparaison, nous allons effectuer des mesures en utilisant 2 requêtes : une récupérant toutes les données de la table, l'autre ne récupérant que le premier enregistrement :
  • fullTableContentQuery : environ 19000 enregistrements pour un total de plus de 20 Mo.
    SELECT [BusinessEntityID], [PersonType], [NameStyle], [Title], [FirstName], [MiddleName], [LastName], [Suffix], [EmailPromotion], [AdditionalContactInfo], [Demographics], [rowguid], [ModifiedDate] FROM [Person].[Person] ORDER BY [BusinessEntityID] ASC
  • singleRowQuery : le premier enregistrement seulement, un peu plus de 1 Ko.
    SELECT TOP 1 [BusinessEntityID], [PersonType], [NameStyle], [Title], [FirstName], [MiddleName], [LastName], [Suffix], [EmailPromotion], [AdditionalContactInfo], [Demographics], [rowguid], [ModifiedDate] FROM [Person].[Person] ORDER BY [BusinessEntityID] ASC


Résultats pour singleRowQuery :
00:00:00.0001810 : ExecuteReader (before) : 0 rows / 0 bytes / 0 buffers
00:00:00.0163239 : ExecuteReader (after) : 0 rows / 1263 bytes / 1 buffers
00:00:00.0165160 : Read (before) : 0 rows / 1263 bytes / 1 buffers
00:00:00.0166315 : Read (after) : 0 rows / 1263 bytes / 1 buffers
00:00:00.0167334 : GetValue (before) : 0 rows / 1263 bytes / 1 buffers
00:00:00.0170658 : GetValue (after) : 0 rows / 1263 bytes / 1 buffers
00:00:00.0173759 : SqlDataReader.Close (before) : 0 rows / 1263 bytes / 1 buffers
00:00:00.0176380 : SqlDataReader.Close (after) : 1 rows / 1263 bytes / 1 buffers
00:00:00.0179771 : SqlDataReader cleanup (before) : 1 rows / 1263 bytes / 1 buffers
00:00:00.0183784 : SqlDataReader cleanup (after) : 1 rows / 1263 bytes / 1 buffers
00:00:00.0187168 : SqlCommand cleanup (before) : 1 rows / 1263 bytes / 1 buffers
00:00:00.0190573 : SqlCommand cleanup (after) : 1 rows / 1263 bytes / 1 buffers
00:00:00.0192853 : SqlConnection.Close (before) : 1 rows / 1263 bytes / 1 buffers
00:00:00.0194869 : SqlConnection.Close (after) : 1 rows / 1263 bytes / 1 buffers

On notera au passage que la valeur SelectRows des statistiques de la connexion n'est alimentée qu'une fois le DataReader clôt (comportement similaire à RecordsAffected).


Résultats pour fullTableContentQuery :
00:00:00.2026912 : ExecuteReader (before) : 0 rows / 0 bytes / 0 buffers
00:00:00.2425445 : ExecuteReader (after) : 0 rows / 8000 bytes / 1 buffers
00:00:00.2427622 : Read (before) : 0 rows / 8000 bytes / 1 buffers
00:00:00.2429330 : Read (after) : 0 rows / 8000 bytes / 1 buffers
00:00:00.2430291 : GetValue (before) : 0 rows / 8000 bytes / 1 buffers
00:00:00.2431401 : GetValue (after) : 0 rows / 8000 bytes / 1 buffers
00:00:00.2432171 : SqlDataReader.Close (before) : 0 rows / 8000 bytes / 1 buffers
00:00:34.6341411 : SqlDataReader.Close (after) : 19972 rows / 26484333 bytes / 6648 buffers
00:00:34.6344105 : SqlDataReader cleanup (before) : 19972 rows / 26484333 bytes / 6648 buffers
00:00:34.6345798 : SqlDataReader cleanup (after) : 19972 rows / 26484333 bytes / 6648 buffers
00:00:34.6347301 : SqlCommand cleanup (before) : 19972 rows / 26484333 bytes / 6648 buffers
00:00:34.6348544 : SqlCommand cleanup (after) : 19972 rows / 26484333 bytes / 6648 buffers
00:00:34.6349754 : SqlConnection.Close (before) : 19972 rows / 26484333 bytes / 6648 buffers
00:00:34.6352253 : SqlConnection.Close (after) : 19972 rows / 26484333 bytes / 6648 buffers

La fermeture du DataReader entraine clairement le téléchargement de ce qu'il restait du jeu de résultats : nous n'avions transféré que 8000 octets avant l'appel à SqlDataReader.Close, 25Mo après.




Raison de ce comportement

Ce comportement n'est pas clairement expliqué en tant que tel dans la documentation de la méthode Close de SqlDataReader, mais la section "remarques" apporte tout de même une piste :
"The Close method fills in the values for output parameters, return values and RecordsAffected, increasing the time that it takes to close a SqlDataReader that was used to process a large or complex query."
Ils ont juste oublié de dire clairement que récupérer les données pour les paramètres output, la valeur de retour et le nombre d'enregistrements affectés implique de transférer l'ensemble des données du jeu de résultats.
Logique dans un sens, mais le préciser clairement aurait été intéressant.




Solution

La solution au problème de transfert de données inutiles est fournie au même endroit :
"When the return values and the number of records affected by a query are not significant, the time that it takes to close the SqlDataReader can be reduced by calling the Cancel method of the associated SqlCommand object before calling the Close method."
Ce qui convient parfaitement à notre cas d'annulation de traitement.


En ajoutant l'appel à SqlCommand.Cancel juste après l'appel à GetValue dans notre méthode de test et en l'exécutant de nouveau avec la requête fullTableContentQuery, la différence est assez claire :

00:00:00.0629712 : ExecuteReader (before) : 0 rows / 0 bytes / 0 buffers
00:00:00.0730612 : ExecuteReader (after) : 0 rows / 8000 bytes / 1 buffers
00:00:00.0731925 : Read (before) : 0 rows / 8000 bytes / 1 buffers
00:00:00.0732918 : Read (after) : 0 rows / 8000 bytes / 1 buffers
00:00:00.0733603 : GetValue (before) : 0 rows / 8000 bytes / 1 buffers
00:00:00.0734498 : GetValue (after) : 0 rows / 8000 bytes / 1 buffers
00:00:00.0735154 : SqlCommand.Cancel (before) : 0 rows / 8000 bytes / 1 buffers
00:00:00.0736983 : SqlCommand.Cancel (after) : 0 rows / 8000 bytes / 1 buffers
00:00:00.0738457 : SqlDataReader.Close (before) : 0 rows / 8000 bytes / 1 buffers
00:00:00.0983481 : SqlDataReader.Close (after) : 0 rows / 88170 bytes / 18 buffers
00:00:00.0985409 : SqlDataReader cleanup (before) : 0 rows / 88170 bytes / 18 buffers
00:00:00.0987143 : SqlDataReader cleanup (after) : 0 rows / 88170 bytes / 18 buffers
00:00:00.0988653 : SqlCommand cleanup (before) : 0 rows / 88170 bytes / 18 buffers
00:00:00.0990717 : SqlCommand cleanup (after) : 0 rows / 88170 bytes / 18 buffers
00:00:00.0992370 : SqlConnection.Close (before) : 0 rows / 88170 bytes / 18 buffers
00:00:00.0994969 : SqlConnection.Close (after) : 0 rows / 88170 bytes / 18 buffers

Nous récupèrons toujours trop de données, mais nettement moins qu'avant (300 fois moins dans le cas présent).
On notera que la valeur SelectRows des statistiques de la connexion n'est pas alimentée.


Il est vraiment important d'appeler Cancel avant Close, surtout d'après cette remarque sur la documentation de cette dernière :
"In some, rare, cases, if you call ExecuteReader then call Close (implicitily or explicitly) before calling Cancel, and then call Cancel, the cancel command will not be sent to SQL Server and the result set can continue to stream after you call Close. To avoid this, make sure that you call Cancel before closing the reader or connection."
Durant tous mes tests j'ai eu le comportement observable sur les mesures affichées plus haut : la méthode SqlDataReader.Close est bloquante jusqu'à fin de transfert des données, donc un appel à SqlCommand.Cancel après ne servirait strictement à rien.


Enfin il est à noter que ExecuteScalar présente le même comportement car son code ne fait pas appel à Cancel avant l'appel à Close, et que dans son cas il est impossible de demander l'annulation de la commande : si ExecuteScalar est utilisé pour lire une valeur sur un jeu d'enregistrements, toutes les données seront transférées au moment de la fermeture du reader utilisé en interne (voir sources de la classe disponibles dans les reference sources).

dimanche 17 août 2014

Port d’écoute TCP ou UDP restant ouvert après l’arrêt du processus : Process.Start et l’héritage de handles


Dans ce post nous allons nous pencher sur une des raisons de fond parmi les moins évidentes pour lesquelles une exception System.Net.Sockets.SocketException peut être levée avec le message "Only one usage of each socket address (protocol/network address/port) is normally permitted" / "Une seule utilisation de chaque adresse de socket (protocole/adresse réseau/port) est habituellement autorisée".
Cette exception peut être reçue directement, comme par exemple lors de l'utilisation des classes TcpListener, UdpClient ou Socket, ou à un niveau plus ou moins profond de la chaine d’innerexceptions suivant la technologie manipulant le socket sous-jacent : dans le cas de WCF elle sera probablement enveloppée dans une instance de System.ServiceModel.AddressAlreadyInUseException avec un message du type "There is already a listener on IP endpoint [IP]:[Port]. This could happen if there is another application already listening on this endpoint or if you have multiple service endpoints in your service host with the same IP endpoint but with incompatible binding configurations." / "Il existe déjà un écouteur sur le point de terminaison IP [IP]:[Port]. Vérifiez que vous n'essayez pas d'utiliser ce point de terminaison plusieurs fois dans votre application et qu'aucune autre application n'écoute sur ce point de terminaison.".
A noter : dans ce post nous parlons bien d'un cas où cette exception est levée avec ce message pour une tentative d'ouverture d'un port d'écoute et non pas le cas où elle est levée avec ce même message lors d'une tentative d'établissement d'une connexion sortante, comme ça peut être le cas lors d'un incident d'épuisement de la plage de ports dynamiques utilisée pour ces connexions (incident bien connu sous le nom "TCP/IP port exhaustion").

Contexte technique de rédaction de ce post : Windows 7 x64 et .NET 4.5.1, mais observé sur d'autres configurations telles que Windows Server 2008 R2 et .NET 4.0 (les tests n'ont pas été réalisés sous Windows 8 / 2012 mais je ne vois à priori pas de raison pour laquelle ce serait différent sur ces plateformes).


Contexte de l'incident

Un service Windows ou une simple application s'exécutant dans une session utilisateur, et pas un service hébergé dans IIS, a été redémarré(e) et n'arrive plus à se positionner en écoute sur le port TCP 12345 (pour notre exemple) alors qu'il/elle le pouvait avant redémarrage.
Il est certain que l'application s'est arrêtée correctement et qu'aucun incident matériel ou réseau n'a eu lieu : toutes les connexions ont été terminées correctement.


Par quel processus est ouvert le port ?

Plusieurs outils permettent de vérifier si un port est ouvert, et par quel processus :
  • netstat, en ligne de commande, fourni avec Windows
  • TCPView, GUI, membre de la suite Sysinternals (une version en ligne de commande est aussi fournie : Tcpvcon).
  • CurrPorts, GUI, par Nirsoft (utilisable aussi en ligne de commande)
Il vaut mieux lancer ces outils avec les privilèges administrateur même si ce n'est pas absolument requis (sauf pour netstat qui ne fonctionnera pas du tout sans ces privilèges avec les paramètres que j'utilise).
Si ces outils sont lancés après l'arrêt du processus de notre application, ils affichent ce qui suit :
TCPView
Capture d'écran de TCPView montrant le port TCP 12345 ouvert en état LISTENING par un processus n'existant plus.
netstat
C:\>netstat -abnop TCP
Active Connections
  Proto  Local Address          Foreign Address        State           PID
[...]
  TCP    0.0.0.0:12345          0.0.0.0:0              LISTENING       5868
 [System]
[...]
CurrPorts (qui permet de filtrer les connexions, donc nous utilisons ce filtre : include:local:tcp:12345)
Capture d'écran de CurrPorts montrant le port TCP 12345 ouvert en état LISTENING soi-disant par le processus System mais dont le PID n'est ni 4, ni 0 : ce n'est donc pas vrai.
Les 3 outils ne sont pas totalement d'accord entres eux :
  • TCPView montre le port TCP 12345 ouvert en état LISTENING par un processus inexistant (PID 5868).
  • netstat et CurrPorts montrent le port TCP 12345 ouvert en état LISTENING soi-disant par le processus System mais dont le PID (5868) n'est ni 4, ni 0 : ce n'est donc pas vrai.
(A noter que s'ils sont lancés avant l'arrêt du processus, TCPView et CurrPorts afficheront peut-être encore le nom du processus qui s'est terminé depuis, au lieu de "System" ou "<non-existent>".)
Aucun processus de PID 5868 ne tourne sur mon système donc nous ne sommes pas très avancés...


Tentative de résolution temporaire du problème : forçage de la fermeture de la connexion

TCPView et CurrPorts permettent de forcer la fermeture de la connexion via le menu contextuel disponible sur cette dernière : "Close Connection" pour TCPView, "Close Selected TCP Connections" pour CurrPorts :
Capture d'écran de l'élément "Close Connection" dans TCPView
Capture d'écran de l'élément "Close Selected TCP Connections" dans CurrPorts
Je ne suis pas forcément fan de cette pratique que je n'encourage pas, on ne sait jamais comment peuvent réagir les applications utilisant la ressource, mais ça peut permettre de débloquer une situation en attendant de corriger le problème de fond.
Là nous avons une connexion associée à un processus inexistant, donc tentons la manipulation.
Echec depuis les 2 outils : TCPView ne dit rien mais la connexion reste ouverte, et CurrPorts affiche un message d'erreur : "Failed to close one or more TCP connections. Be aware that you must run this tool as admin in order to close TCP connections." (j'avais pourtant bien lancé cet outil avec les privilèges administrateur comme je l'ai conseillé plus haut).
Nous verrons plus bas qu'il est en réalité possible, dans certains cas, d'obtenir la fermeture de cette connexion sans pour autant terminer le processus qui la tient ouverte.


Cause de fond du problème : l'héritage de handles

En examinant la liste des processus s'exécutant sur la machine j'en ai vu un que je savais être un processus esclave de celui qui écoutait sur le port 12345 et ce n'est qu'à ce moment-là que je me suis souvenu d'un mécanisme disponible sur le lancement de processus sous certaines conditions : l'héritage de handles.
Il faut savoir que, au moment où je rédige cet article (.NET 4.5.1), la classe Process dispose de 2 moyens de lancer un nouveau processus lors de l'appel à la méthode Start :
Une seule de ces 3 fonctions permet d'activer le mécanisme d'héritage de handles : CreateProcess
BOOL WINAPI CreateProcess(
  _In_opt_     LPCTSTR lpApplicationName,
  _Inout_opt_  LPTSTR lpCommandLine,
  _In_opt_     LPSECURITY_ATTRIBUTES lpProcessAttributes,
  _In_opt_     LPSECURITY_ATTRIBUTES lpThreadAttributes,
  _In_         BOOL bInheritHandles,
  _In_         DWORD dwCreationFlags,
  _In_opt_     LPVOID lpEnvironment,
  _In_opt_     LPCTSTR lpCurrentDirectory,
  _In_         LPSTARTUPINFO lpStartupInfo,
  _Out_        LPPROCESS_INFORMATION lpProcessInformation
);

[...]
bInheritHandles [in]
If this parameter TRUE, each inheritable handle in the calling process is inherited by the new process. If the parameter is FALSE, the handles are not inherited. Note that inherited handles have the same value and access rights as the original handles.
[...]
Et justement si on examine le code de la classe Process dans .NET 4.5.1, disponible au travers du programme Reference Source, on s'aperçoit que l'appel à CreateProcess est bel et bien effectué en passant true pour le paramètre bInheritHandles :
Extrait du code de la méthode StartWithCreateProcess qui nous intéresse  :
retVal = NativeMethods.CreateProcess (
       null,               // we don't need this since all the info is in commandLine
       commandLine,        // pointer to the command line string
       null,               // pointer to process security attributes, we don't need to inheriat the handle
       null,               // pointer to thread security attributes
       true,               // handle inheritance flag
       creationFlags,      // creation flags
       environmentPtr,     // pointer to new environment block
       workingDirectory,   // pointer to current directory name
       startupInfo,        // pointer to STARTUPINFO
       processInfo         // pointer to PROCESS_INFORMATION
   );


La classe Process utilise ShellExecuteEx pour lancer le nouveau processus tant que la propriété UseShellExecute de l'instance de ProcessStartInfo passée à ou créée par la méthode Start vaut true.
Dès que UseShellExecute vaut false, la classe utilise CreateProcess si aucun username/password n'a été spécifié, ou CreateProcessWithLogonW dans le cas contraire.
Donc dans le cas où le processus esclave est lancé via CreateProcess, le port d'écoute ne sera libéré que quand à la fois le processus maitre et le processus esclave auront terminé leur exécution (ou simplement fermé le handle vers le socket ouvert).
Si vous vous retrouvez dans cette situation, que votre processus esclave doit absolument terminer son travail avant d'être arrêté et que vous êtes certains que le handle du socket qui a été hérité n'est pas utilisé dans le processus esclave vous pouvez peut-être vous en sortir en forçant la fermeture du handle (avec Process Explorer ou Process Hacker), avec les mêmes réserves que pour le forçage de fermeture de la connexion plus tôt dans ce post. Le handle à chercher est typé File et nommé "\Device\Afd". Si notre processus en possède plusieurs, ça va être compliqué : je ne connais pas de méthode permettant de retrouver les informations du socket en partant du handle.

Autre point à noter : la documentation de CreateProcess dit ceci pour le paramètre bInheritHandles : "Note that inherited handles have the same value and access rights as the original handles."
Autrement dit : si le processus esclave en lance un troisième selon les mêmes modalités alors le handle du socket sera aussi transmis à ce nouveau processus, et ainsi de suite.


Peut-on éviter l'héritage du handle de socket quand Process.Start passe par CreateProcess ?

A ma connaissance il n'existe pas de moyen fiable d'empêcher cet héritage de handle lors de l'appel à CreateProcess par la classe Process.
J'ai bien vu quelques informations concernant l'utilisation de SetHandeInformation sur le handle du socket (accessible via la propriété Handle) mais j'ai aussi lu que la présence de certains Layered Service Providers (LSP) pouvait rendre ce changement inefficace, entrainant un héritage systématique des handles de sockets par les processus enfants dès lors que le paramètre bInheritHandles vaut true.
Il vaut donc mieux avoir un design prenant en compte et compensant ce problème d'héritage du handle de socket, ou permettant de s'assurer que UseShellExecute pourra conserver une valeur true.