Algo d'écriture dans un fichier texte, sans ralentir l'application

Version imprimable

Bonjour à tous,

J'essaie d'optimiser un soft. J'ai grandement réussi à optimiser la partie SQL (MySQL et SQlite), mais en parallèle j'ai mis en place la capture des requêtes SQL.
Reprenant un logiciel existant avec peu d'information, j'essais de comprendre l'ancienne logique de synchronisation, qui ne semble pas top, puisqu'il y a parfois des pertes de données.

Bref, j'ai donc ajouté la capture des requêtes que j'écris dans un fichier texte. La 1er synchronisation contient prés de 5000 requêtes. Ajouter l'écriture dans le fichier texte en même temps ralentit vraiment beaucoup la synchro.

Ce que j'ai fait:

Je créé une list qui contient les requêtes, et d'un autre coté j'ai un timer à 1ms qui interroge la list, récupère et supprime le 1er de cette list, toutes les 100 requêtes ou lorsque la liste est vide je sauvegarde le fichier, le tout protégé par un sémaphore. pour éviter les collisions sur la list.
Code:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 List<string> ListWrite; Semaphore Sem_SecureList = new Semaphore(initialCount: 1, maximumCount: 1, name: "Sem_SecureList"); private void AddListWrite(Dictionary<int,string> Dic) { if (ListWrite == null) ListWrite = new List<string>(); if (Dic.Count > 0) { Sem_SecureList.WaitOne(); foreach (int key in Dic.Keys) { if(Dic[key] != "") ListWrite.Add(Dic[key]); } Sem_SecureList.Release(); } } private string GetListWrite() { string ret = ""; Sem_SecureList.WaitOne(); if(ListWrite.Count > 0) { ret = ListWrite[0]; ListWrite.RemoveAt(0); } Sem_SecureList.Release(); return ret; } //Le timer que j'arrête et redémarre à chaque fois private void OnTimerLoop_Tick(object state) { TimerLoopStop(); string line = GetListWrite(); if (line != "") { WriteLogDebug(line); }else { if (sr != null) { sr.Close(); sr = null; } } TimerLoopStart(); }
Cela fonctionne bien, mais la partie écriture du texte est toujours très lente, ou du moins elle me "semble" anormalement lente. Au moins la partie SQL n'est pas affectée et va bien plus vite, c'est ce qui importe, car cette partie d'écriture du texte est là que pour du débogage et pour le moment mieux comprendre la synchronisation.

Je pensais à une limitation du basculement du sémaphore, mais cela bloquerais aussi le thread des requêtes SQL, ce qui n'est pas le cas.

Pour info, le traitement de la synchro dur (à la louche) 10 / 15 secondes pour la partie SQL, mais la partie texte cela dur bien 45 secondes, le fichier fait 1700ko à la fin de la lecture des trames de la 1ere synchro.

Pour lancer le débogage, le logiciel vérifie si un fichier texte est présent. Si ce fichier texte est présent, mais vide le débogage enregistre toutes les requêtes. Si ce fichier texte contient des lignes, il filtre et enregistre uniquement les requêtes qui contiennent ces lignes, ou si la ligne est précédé de ! il enregistre toutes les requêtes, sauf celle qui contiennent la ligne.

Comment optimiser cela? J'ai cherché sans rien trouver, ou je donne pas les bons termes.

Merci

16/12/2022, 08h58
François DORIN

Il faudrait voir le code complet pour se faire une idée.

De manière général, les I/O peuvent être très lentes, surtout sur un disque dur classique (non SSD) ou sur un chemin réseau. De plus, de l'extrait, j'ai l'impression que tu ouvres/fermes le fichier de sortie très souvent au lieu de le "flusher" régulièrement.

Ouvrir un fichier, aller à la fin de celui-ci, y écrire du texte, le fermer, et recommencer à chaque opération d'écriture est aussi très consommateur en temps (car l'OS met à jour les métadonnées dans le système de fichiers, etc à chaque fois).
16/12/2022, 10h12
megamario

Citation:

Envoyé par François DORIN

Il faudrait voir le code complet pour se faire une idée.

De manière général, les I/O peuvent être très lentes, surtout sur un disque dur classique (non SSD) ou sur un chemin réseau. De plus, de l'extrait, j'ai l'impression que tu ouvres/fermes le fichier de sortie très souvent au lieu de le "flusher" régulièrement.

Ouvrir un fichier, aller à la fin de celui-ci, y écrire du texte, le fermer, et recommencer à chaque opération d'écriture est aussi très consommateur en temps (car l'OS met à jour les métadonnées dans le système de fichiers, etc à chaque fois).

Bonjour et merci,

Alors non, je n'effectue pas une fermeture à chaque fois, mais uniquement lorsque le buffer (la list est vide, dans le code présenté) et vu que la partie SQL est plus rapide, la list se vide bien plus tard. Ensuite les synchro sont réglées toutes les 5 minutes, mais il y a un pooling pour vérifier la présence de la base distante MySQL, sa aussi je pense que je pourrais le changer un peu, il est trop rapide ce pooling de vérification et interviens même pendant la synchro. Et il y a aussi l'utilisateur qui peut intervenir à tout moment.

Je n'est pas indiqué c'est vrai, la méthode "WriteLogDebug", elle ne faisait qu'ajouter la date et l'heure en cours, instancier "sr" s'il est null, et écrire la requêtes.

Depuis j'ai ajouté la date et l'heure directement lors de la création de la trame, je pourrais dont ajouter directement le sr.Writeline(line) directement dans le OnTimerLoop_Tick() à la place de WriteLogDebug.

La trame est constituée de plusieurs informations: donc la date et l'heure, la requête, le type de requête (SELECT, INSERT, DELETE etc...), la table concernée, la méthode qui a envoyer la requête ainsi que la ligne et la class, le tout séparer par un ; pour former un CSV afin de facilement faire des tris dans Excel par la suite, pour rappel c'est pour du débogage et comprendre la méthodologie de l'ancien développeur qui n'a pas écrit de documentation, pas d'étude préalable non plus.

Depuis j'ai aussi ajouté un compteur pour écrire et fermer le fichier toutes les 100 lignes, afin de voir défiler le poids du fichier dans l'explorateur Windows, cela ne ralenti pas plus (ou imperceptible), mais je ne connaissais pas flush que je vais utiliser, merci.

Certes je sais que les flux en écriture sont assez long et n'aillant que très peu pratiqué les BDD avant, j'ai été surpris de leur rapidité. Bon je les ai optimisé déjà, car il y avait une ouverture, écriture, fermeture de la BDD, presque à chaque requête. Il y avait des boucles qui synchronisait plus de 500 lignes dans la BDD avec une ouverture fermeture à chaque fois.!!!
Il avait fait cela, car en même temps que la synchronisation, sur les postes locaux il y a une BDD Sqlite, et les utilisateurs ont un appareil à scanner et renseigner des infos le tout s'inscrivant dans la BDD local... Sachant que pendant la synchro il y a des delete...., le tout en multithread, vous comprendrez aisément qu'il peut y avoir des clash, des pertes de données... et une connexion de la BDD SQlite en même temps....

Pour mon problème, je pense plus à ma mauvaise utilisation du sémaphore et du timer qui est réglé au minimum à 1ms pour faire ma boucle, mais j'arrête et redémarre à chaque cycle pour pas que cela se chevauche aussi.

Encore que le sémaphore doit bien se comporter puisque les ajouts dans la liste ne ralentisse pas du tout les transaction SQL. mais je suis bien obligé de mettre une protection sur cette list. Ecriture d'un coté, lecture et effacement de l'autre( ce dernier étant peut être aussi un facteur de ralentissement.

Merci pour l'information du "flush".
16/12/2022, 10h47
François DORIN

Je ne pense pas que le sémaphore soit le goulot d'étranglement vu le nombre de requêtes à écrire (5000) et la durée observée (+ de 40s).
Je ne pense pas non plus que cela soit le timer (même à 1ms, 5000 lignes) qui doit rajouter dans les 5s à tout casser.

L'ouverture/fermeture d'un fichier peut être très impactant, avec un élément à prendre en compte que j'ai oublié dans mon dernier message : l'antivirus ! Ce dernier peut venir s'intercaler pour protéger le système en détectant et bloquant les comportements suspicieux. Cette détection a un coût. Pas forcément très visible pour 1 ouverture, mais pour 50...

Maintenant, sans le code complet, il va être difficile de vous aider. Car il y a de nombreuses choses qui pourraient sans doute être améliorées :
- usage d'un sémaphore binaire : est-il nécessaire qu'il soit nommé ? Si non, l'usage d'un mutex simplifierait le code
- utilisation d'une Queue<T> au lieu d'une List<T>, voire même d'un ConcurrentQueue<T> qui gérerait la concurrence pour vous
- mise en place d'un système producteur/consommateur (mais dans ce cas, il faudra garder le sémaphore, et même en rajouter un autre, et ne pas utiliser ConcurrentQueue mais Queue ou List) => permettra de ne plus dépendre du timer

Malheureusement je n'est pas la possibilité de mettre le code complet.

Mais c'est bon, j'ai créé un projet de test ou je charge l'un de me fichier précédemment enregistrer dans une list (identique à mon projet).

Ensuite j'ai enregistré cette liste en passant dans un 1er temps dans une simple boucle, mais en gardant le mécanisme de récupération de la 1er donnée de la liste et la supprimer de cette même liste. L'enregistrement était quasi instantané.
J'ai rajouté au fur et à mesure, le sémaphore et c'est quand j'ai ajouté le timer de 1ms que cela a grandement allonger la durée d'écriture.

Du coup j'ai changé le rôle du timer et passé à 200ms, mais au lieu d'aller chercher les données et les écrire, il regarde avant s'il y a des données dans la liste et s'il y en a il lance une boucle qui va lire et vide la liste (en écrivant les données bien sûr).
Code:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 private void OnTimerLoop_Tick(object state) { TimerLoopStop(); try { Sem_SecureLoop.WaitOne(); int nbList = ListWrite.Count; Sem_SecureLoop.Release(); if (nbList > 0) { string line = GetListWrite(); if (line == "") { TimerLoopStart(); return; } if (sr == null) sr = new StreamWriter(FilePathLogCommandBDD, true, System.Text.Encoding.UTF8); do { sr.WriteLine(line); NbLine++; line = GetListWrite(); } while (line != ""); if (sr != null) { sr.Close(); sr = null; } } } catch (Exception ex) { Var.Sql_Query.WriteInLogError(gClasse, "OnTimerLoop_Tick", "ErrorSystem", 0, 0, ex.ToString()); } TimerLoopStart(); }
Voila c'est parfait, même si ferme et rouvre le streamwriter, c'est aussi rapide maintenant que le traitement SQL, enfin imperceptible.

Merci en tout cas, car vous m'avez donné pas mal de petite info que je ne connaissais pas.

Quelques axes, en vrac, pour accélérer l'écriture dans un fichier :
- Ca sert à rien de faire du ligne à ligne. Collez tout votre texte à écrire dans un buffer de plusieurs lignes et collez des pavés de 4 ou 8 Ko à la fois, ça sera bien plus performant (le mieu étant d'aligner ce buffer avec la taille d'un secteur sur le disque).
- Comme déjà dit, ouvrir et fermer le fichier ça prend au minimum 90% du temps d'écriture...
- Enfin, même si ça demande un peu de boulot par la suite pour vérifier que tout est bien écrit avant d'arrêter le programme, utiliser sw.WriteAsync() évitera d'attendre bêtement à chaque écriture.

-- Edit : je voulais mesurer un peu l'impact de différentes approches, et contre toute attente, l'asynchrone est (de très loin) le plus lent (enfin, mise à part si on prend en compte la méthode avec ouverture/fermeture du fichier à chaque ligne). Le seul vrai avantage de l'asynchrone du coup c'est... d'être asynchrone. Point. Mais si on veut gérer du parallélisme, je doute qu'on passe pas de l'asynchrone au niveau écriture disque, dans la mesure où de toute façon on écrit séquentiellement dans un seul fichier ici : on fera plutôt un thread pour la gestion du log et un thread pour la gestion du SQL par exemple). Pour arriver à des performances pas trop pourries avec le parallélisme j'ai du systématiquement attendre les écritures, ce qui en soit est complètement abhérant...

Voici un code source complet et le résultat sur mon PC.
A noter que pour de l'écriture contigüe... le SSD ça change absolument rien du tout ! Même avec la méthode qui ouvre/ferme sans arrêt c'est plus lent !

Program.cs

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
 
using FastWriteFile;
using System.Diagnostics;
 
// This program tries to show the impact of different ways to write in files
 
string[] PATHS = { "E:\\temp" /* HDD */, "K:\\temp" /* SSD */ };
const int NB_LINES = 100000; // Will create 3+MB files
 
foreach (string path in PATHS)
{
    Stopwatch sw = new();
    Console.WriteLine($"Write in path : {path}");
 
    Console.Write("BadLogFile");
    sw.Start();
    using (BadLogFile log = new(path))
    {
        log.WriteLines(NB_LINES);
        Console.WriteLine();
        Console.WriteLine("Finishing");
    }
    sw.Stop();
    Console.WriteLine($"Elapsed time: {sw.ElapsedMilliseconds}ms");
    Console.WriteLine();
 
    Console.Write("SlowLogFile");
    sw.Restart();
    using (SlowLogFile log = new(path))
    {
        log.WriteLines(NB_LINES);
        Console.WriteLine();
        Console.WriteLine("Finishing");
    }
    sw.Stop();
    Console.WriteLine($"Elapsed time: {sw.ElapsedMilliseconds}ms");
    Console.WriteLine();
 
    Console.Write("SimpleLogFile");
    sw.Restart();
    using (SimpleLogFile log = new(path))
    {
        log.WriteLines(NB_LINES);
        Console.WriteLine();
        Console.WriteLine("Finishing");
    }
    sw.Stop();
    Console.WriteLine($"Elapsed time: {sw.ElapsedMilliseconds}ms");
    Console.WriteLine();
 
    Console.Write("AsyncLogFile");
    sw.Restart();
    using (AsyncLogFile log = new(path))
    {
        log.WriteLines(NB_LINES);
        Console.WriteLine();
        Console.WriteLine("Finishing");
    }
    sw.Stop();
    Console.WriteLine($"Elapsed time: {sw.ElapsedMilliseconds}ms");
    Console.WriteLine();
}

BadLogFile.cs => Attention, VRAIMENT, faut pas ouvrir/fermer le fichier à chaque fois, c'est abominablement lent ! J'ai implémenté ici IDisposable mais ça sert à rien, c'était juste pour que les 4 classes soient appelés de la même manière.

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
 
namespace FastWriteFile
{
    /// <summary>
    /// This class opens and closes the file each time it recieves a new line.
    /// NERVER do this.
    /// </summary>
    internal class BadLogFile : IDisposable
    {
        private readonly string _filename;
 
        public BadLogFile(string path)
        {
            _filename = Path.Combine(path, "bad.txt");
            if (File.Exists(_filename))
            {
                File.Delete(_filename);
            }
        }
 
        public void WriteLines(int count)
        {
            for (int i = 0; i < count; i++)
            {
                WriteLine($"Ceci est la ligne numéro {i}");
                if (i % 1000 == 999) Console.Write('.');
            }
        }
 
        public void WriteLine(string line)
        {
            using (StreamWriter file = new(_filename, true))
            {
                file.WriteLine(line);
            }
        }
 
        private bool disposedValue;
 
        protected virtual void Dispose(bool disposing)
        {
            if (!disposedValue)
            {
                if (disposing)
                {
                }
                disposedValue = true;
            }
        }
 
        public void Dispose()
        {
            Dispose(disposing: true);
            GC.SuppressFinalize(this);
        }
    }
}

SlowLogFile.cs => Attention, au Flush() ça va perdre un temps perceptible, à n'utiliser que si on en a vraiment besoin !

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
 
namespace FastWriteFile
{
    /// <summary>
    /// This class opens the file one time, then flush the file each time it recieves a new line.
    /// NERVER do this.
    /// </summary>
    internal class SlowLogFile : IDisposable
    {
        private readonly StreamWriter file;
 
        public SlowLogFile(string path)
        {
            file = new(Path.Combine(path, "slow.txt"), false);
        }
 
        public void WriteLines(int count)
        {
            for (int i = 0; i < count; i++)
            {
                WriteLine($"Ceci est la ligne numéro {i}");
                if (i % 1000 == 999) Console.Write('.');
            }
        }
 
        public void WriteLine(string line)
        {
            file.WriteLine(line);
            file.Flush();
        }
 
        private bool disposedValue;
 
        protected virtual void Dispose(bool disposing)
        {
            if (!disposedValue)
            {
                if (disposing)
                {
                    file.Close();
                    file.Dispose();
                }
                disposedValue = true;
            }
        }
 
        public void Dispose()
        {
            Dispose(disposing: true);
            GC.SuppressFinalize(this);
        }
    }
}

SimpleLogFile.cs > C'est finalement la méthode la plus simple la plus rapide :lol:

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
 
namespace FastWriteFile
{
    /// <summary>
    /// This class opens the file one time and let the system to flush when needed.
    /// This can do the job.
    /// </summary>
    internal class SimpleLogFile : IDisposable
    {
        private readonly StreamWriter file;
 
        public SimpleLogFile(string path)
        {
            file = new(Path.Combine(path, "simple.txt"), false);
        }
 
        public void WriteLines(int count)
        {
            for (int i = 0; i < count; i++)
            {
                WriteLine($"Ceci est la ligne numéro {i}");
                if (i % 1000 == 999) Console.Write('.');
            }
        }
 
        public void WriteLine(string line)
        {
            file.WriteLine(line);
        }
 
        private bool disposedValue;
 
        protected virtual void Dispose(bool disposing)
        {
            if (!disposedValue)
            {
                if (disposing)
                {
                    file.Close();
                    file.Dispose();
                }
                disposedValue = true;
            }
        }
 
        public void Dispose()
        {
            Dispose(disposing: true);
            GC.SuppressFinalize(this);
        }
    }
}

AsyncLogFile.cs => Mauvaise surprise, l'asynchrone c'est lent. J'ai laissé en commentaire une partie de mes tentatives pour avoir un code plus asynchrone encore, mais c'était 10 fois plus lent ! Visiblement ça le perturbe de devoir remettre dans l'ordre les lignes !

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
 
using System.Text;
 
namespace FastWriteFile
{
    /// <summary>
    /// This class works exclusively with async methods, and also user OS layer async capacities : should be way faster.
    /// You cound always do this... If it works!
    /// </summary>
    internal class AsyncLogFile : IDisposable
    {
        //List<Task> tasks = new();
        private readonly FileStream file;
 
        public AsyncLogFile(string path)
        {
            file = new(Path.Combine(path, "async.txt"), FileMode.Create, FileAccess.Write, FileShare.None, bufferSize: 4096, useAsync: true);
        }
 
        public void WriteLines(int count)
        {
            for (int i = 0; i < count; i++)
            {
                WriteLine($"Ceci est la ligne numéro {i}");
                if (i % 1000 == 999) Console.Write('.');
            }
        }
 
        public void WriteLine(string line)
        {
            byte[] b = Encoding.UTF8.GetBytes(string.Concat(line, Environment.NewLine));
            //Task t = file.WriteAsync(b, 0, b.Length);
            //tasks.Add(t);
 
            file.WriteAsync(b, 0, b.Length).Wait();
        }
 
        private bool disposedValue;
 
        protected virtual void Dispose(bool disposing)
        {
            if (!disposedValue)
            {
                if (disposing)
                {
                    //await Task.WhenAll(tasks);
                    //tasks.Clear();
                    file.Close();
                    file.Dispose();
                }
                disposedValue = true;
            }
        }
 
        public void Dispose()
        {
            Dispose(disposing: true);
            GC.SuppressFinalize(this);
        }
    }
}

Sortie : E: est un HDD et K: un SSD

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
 
Ecriture dans le dossier : E:\temp
BadLogFile....................................................................................................
Finishing
Elapsed time: 10845ms
 
SlowLogFile....................................................................................................
Finishing
Elapsed time: 483ms
 
SimpleLogFile....................................................................................................
Finishing
Elapsed time: 22ms
 
AsyncLogFile....................................................................................................
Finishing
Elapsed time: 123ms
 
Ecriture dans le dossier : K:\temp
BadLogFile....................................................................................................
Finishing
Elapsed time: 12272ms
 
SlowLogFile....................................................................................................
Finishing
Elapsed time: 306ms
 
SimpleLogFile....................................................................................................
Finishing
Elapsed time: 17ms
 
AsyncLogFile....................................................................................................
Finishing
Elapsed time: 108ms

17/12/2022, 19h06
François DORIN

Intéressant comme petit benchmark.

Concernant les performances de l'asynchrone (ou plutôt le manque de performance), c'est parce que tu fais du faux asynchrone.

Appeler une méthode Async et faire un wait derrière, c'est transformer un asynchrone en synchrone. Tu rajoutes simplement une gestion d'état (car c'est comme ça que sont gérer les méthodes async) qui alourdi grandement le travail à effectuer, même si syntaxiquement, cela ne représente pas grand chose.

Mais cela devient très difficile de faire de l'asynchrone vraiment asynchrone si on souhaite respecter l'ordre d'écriture des lignes. La seule méthode que je verrai vraiment asynchrone, c'est de récupérer la Task renvoyée par WriteAsync, et d'écrire la prochaine ligne en chainant via ContinueWith, et d'attendre, au final, la fin de la dernière tâche.

Mais même là, cela m'étonnerait qu'il y ait un gain vu le contexte. Il faudrait à la rigueur forcer le traitement sur un autre thread (car oui, asynchrone ne signifie pas multithreading !). Mais même là, je ne suis pas certain, pour un cas aussi simple, que le temps de traitement soit moindre que la version simple. Le seul avantage, ce serait sur un programme long, où finalement, le temps de traitement serait pris sur un thread autre que le thread de traitement, et donc un impact quasi nul sur ce dernier.

Donc oui, pour terminer, ce qu'il faut retenir des traitements asynchrones : ils sont par nature plus long qu'en synchrone. L'avantage est qu'ils permettent :
- soit de tirer bénéfices de plusieurs threads, et donc au final, de compenser l'augmentation du cout de traitement par une augmentation de la capacité de calcul
- soit de profiter d'un moment où le thread principal est en attente pour réaliser des traitements en attente, c'est-à-dire de profiter d'un moment où le thread ne fait rien pour faire quelque chose (ce qui peut donner l'impression d'aller plus vite)
19/12/2022, 08h26
megamario

Sincèrement merci beaucoup à vous pour cette leçon.

J'en attendait pas autant, super.
Je vais me tester tout sa.
J'ai appris plein de petit truc, MERCI encore.