Dalam artikel ini saya telah menempatkan tolok ukur panggilan paling pribadi dari penebang. Saya melakukan semua percobaan pada log4net dan NLog, pada Intel Windows 10 x64 dengan M.2 SSD.

Hasil mentah dapat dilihat di GitHub . Kode dalam repositori yang sama (untuk menjalankan, Anda memerlukan .Net 4.7.2 + Microsoft Visual Studio 2017+).

Apa, bagaimana dan mengapa - di bawah luka.

Agar tidak membaca untuk waktu yang lama, tabel hasil:

NoOpLogging

Pertama, mari kita perkirakan berapa banyak kita menghabiskan waktu memanggil metode untuk logging, yang pada akhirnya tidak akan menghasilkan apa-apa. Dalam kebanyakan kasus (dalam pengalaman saya), Debug verbose dinonaktifkan pada server pertempuran, tetapi tidak ada yang menghapus panggilan.

Pertama, hasilnya:

Dan kodenya:

void Log4NetNoParams() => _log4Net.Debug("test"); void Log4NetSingleReferenceParam() => _log4Net.DebugFormat("test {0}", _stringArgument); void Log4NetSingleValueParam() => _log4Net.DebugFormat("test {0}", _intArgument); void Log4NetMultipleReferencesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void Log4NetMultipleValuesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); void NLogNetNoParams() => _nlog.Debug("test"); void NLogNetSingleReferenceParam() => _nlog.Debug("test {0}", _stringArgument); void NLogNetSingleValueParam() => _nlog.Debug("test {0}", _intArgument); void NLogNetMultipleReferencesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void NLogNetMultipleValuesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); 

Pertama, mari kita tentukan mengapa tes semacam itu dipilih:

• Percobaan dilakukan di perpustakaan paling populer.

• NLog dan log4net memiliki tanda tangan fungsi yang berbeda untuk sejumlah kecil argumen:

  
  
  • log4net:
  
  

   void DebugFormat(string format, object arg0) 

  
  
  • Nlog:
  
  

   void Debug(string message, string argument) void Debug<TArgument>(string message, TArgument argument) 

  
  
  • Teori: ketika mentransfer tipe signifikan ke log4net, tinju akan muncul, yang hanya menghabiskan waktu prosesor dan tidak mengarah ke apa pun. Dalam kasus NLog, tidak ada perilaku seperti itu, jadi yang terakhir harus bekerja lebih cepat.
  
  
• Tanda tangan untuk sejumlah besar argumen di perpustakaan kira-kira sama, jadi saya ingin tahu:
  
  • Betapa jauh lebih efisien untuk memanggil metode dengan sejumlah kecil parameter.
  • Apakah ada perbedaan dalam kecepatan memanggil metode "Apakah ... Diaktifkan" antara dua perpustakaan

Dan sekarang hasil analisisnya:

• Karena penggunaan argumen generik di NLog, ini berfungsi lebih cepat untuk kasus ketika penebangan langsung tidak diperlukan. Yaitu, untuk kasus ketika dalam program Debug Anda tingkat diaktifkan hanya pada sistem pengujian, hanya mengubah perpustakaan dapat mempercepat perangkat lunak (dan meningkatkan kehidupan pengguna).
• Jika Anda telah logon dimatikan dan Anda ingin memanggil metode dengan sejumlah besar argumen, maka lebih efisien untuk membaginya menjadi dua. Karena itu, pemanggilan metode di atas akan bekerja sepuluh kali lebih cepat.
• Ketika Anda menulis fungsi yang dapat mengambil objek apa pun, seringkali paling efektif untuk bingung dan membuat fungsi generik. Karena optimasi yang sederhana, kode akan bekerja lebih cepat (ini terlihat jelas dalam perbedaan waktu antara panggilan ke Log4NetSingleReferenceParam dan Log4NetSingleValueParam )

Filelogging

Sebagian besar program (menurut pengamatan saya) masih mencatat hasil ke file, jadi untuk perbandingan kami memilih operasi ini. Untuk kesederhanaan, kami hanya mengambil konfigurasi para penebang ketika file ditulis ke file tanpa buffering, tanpa kunci tambahan, dll.

Hasil:

Kode yang digunakan:

• log4net:

 var roller = new RollingFileAppender(); roller.ImmediateFlush = true; roller.RollingStyle = RollingFileAppender.RollingMode.Once; roller.MaxFileSize = 128 * 1000 * 1000; 

• Nlog:

 new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = false, KeepFileOpen = false }; 

Seperti yang Anda lihat, konfigurasi para penebang kurang lebih sama, dan sesuai dengan hasilnya:

• NLog sedikit lebih cepat dari log4net, sekitar 15%.
• Menurut tes, ternyata lebih efisien untuk mencatat lebih sedikit parameter. Namun, jangan lupa bahwa dengan jumlah parameter yang lebih besar, string yang dihasilkan juga diperluas. Oleh karena itu, tabel hanya membandingkan NLog dengan log4net dengan benar.

NLog - berbagai jenis kunci

Kode Sumber:

 new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = XXXXX, KeepFileOpen = YYYYY }; 

Jika kami menempatkan semua kombinasi yang memungkinkan sebagai pengganti XXXXX dan YYYYY, kami mendapatkan tes dari tabel.

Hasilnya cukup dapat diprediksi:

• Jika Anda mengaktifkan ConcurrentWrites, maka sistem akan terus-menerus mengambil dan memberikan Mutex, yang tidak gratis. Tetapi, seperti yang kita lihat, menulis satu baris ke file kira-kira setara dengan satu kunci sistem.
• Menutup dan membuka file, seperti yang kita lihat, lebih memengaruhi kinerja sistem. Dalam contoh dengan KeepFileOpen=true untuk setiap operasi logging, kami membuat file (bersama-sama dengan Handle), menulis ke disk, bernama Flush, kembali Handle dan juga membuat banyak operasi kap mesin. Akibatnya, kecepatan turun ratusan kali.

Logging asinkron dan metode penguncian berbeda

Perpustakaan NLog juga dapat melakukan semua operasi IO pada utas lainnya, segera membebaskan yang sekarang. Dan dia melakukannya dengan kompeten, menjaga urutan peristiwa, menjatuhkan semua data dalam blok, dan di setiap blok bilangan bulat adalah nomor peristiwa (sehingga garis yang dipotong tidak diperoleh), dan seterusnya.

Hasil dari berbagai metode non-pemblokiran:

Perbandingan pendekatan pemblokiran dan asinkron akan lebih jauh, tetapi di sini - hanya yang terakhir.

Kode AsyncTargetWrapper :

 new AsyncTargetWrapper(fileTargetWithConcurrentWritesAndCloseFileAsync) { OverflowAction = AsyncTargetWrapperOverflowAction.Block, QueueLimit = 10000 } 

Seperti yang Anda lihat, pengaturan pembungkus sedemikian rupa sehingga pembuangan langsung ke file tidak memakan waktu cukup lama. Dengan demikian, buffer besar terakumulasi, yang berarti bahwa semua operasi sumber daya intensif seperti "file terbuka" dilakukan sekali untuk seluruh blok. Namun, algoritma semacam itu membutuhkan memori tambahan (dan banyak).

Kesimpulan:

• Jika output asinkron digunakan, tidak masalah apa pun pengaturan output dengan file yang digunakan. Anda dapat membuka dan menutup file setiap kali, dengan buffer besar itu akan hampir tak terlihat.
• Semua pengukuran adalah benar hanya untuk kasus ketika data memerah ke disk pada kecepatan yang sama dengan pengisian buffer (saya melakukan ini karena sistem file cepat + jeda alami antara pengukuran).

Logging sinkron dan asinkron

Kesimpulan:

• Meskipun disk cepat (dalam kasus saya - M.2 SSD), menulis ke file dalam aliran lain mempercepat pekerjaan beberapa kali. Jika aplikasi Anda menulis ke disk HDD, dan bahkan berjalan di mesin virtual, maka keuntungannya akan lebih besar.
• Namun, meskipun pengoperasian kode asinkron yang bahkan lebih cepat, kurangnya pencatatan memberikan hasil yang lebih besar (walaupun sedikit berbeda, tergantung pada pustaka).

Menciptakan Penebang

Hasil:

Apa yang diuji:

 [Benchmark] public object CreateLog4NetFromString() { return LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _log4NetStringLogIndex) % 1000)); } [Benchmark] public object CreateNLogFromString() { return NLog.LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _nLogStringLogIndex) % 1000)); } [Benchmark] public object CreateLog4NetLogger() { return new [] { LogManager.GetLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogTypeOfLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogDynamicLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(), // x16 times }; } 

Komentar penting: sayangnya, sulit bagi saya untuk membuat tolok ukur yang dapat direproduksi yang tidak mengarah ke Memori Kehabisan, tetapi yang akan membuat penebang yang berbeda (mis. Untuk jenis yang berbeda, untuk garis yang berbeda dan sebagainya).

Namun, setelah mempelajari karya perpustakaan, saya menemukan bahwa hampir semua operasi yang paling sulit dilakukan untuk membuat kunci logger (mis., Menentukan nama, menghapus argumen Generik, dan sebagainya).
Selain itu, untuk menstabilkan patokan untuk membuat logger untuk log4net, perlu untuk melakukan bukan hanya satu operasi, tetapi 16 (mis. Sebuah array dari 16 objek yang identik dikembalikan). Jika Anda tidak mengembalikan apa pun, maka .Net mengoptimalkan eksekusi untuk saya (tampaknya, tidak mengembalikan hasilnya), yang menyebabkan hasil yang salah.

Dan kesimpulannya:

• Logger dibuat paling cepat dari string (NLog lebih cepat lagi, namun, perbedaan antara perpustakaan kecil, mengingat logger dibuat bukan hanya seperti itu, tetapi untuk pekerjaan selanjutnya dengan mereka).
• log4net lebih cepat dari NLog saat menginisialisasi proyek. Mungkin ini disebabkan oleh caching tambahan di sisi NLog, yang membantu mempercepat panggilan langsung ke Debug , Info , dll. Faktanya, setiap ILogger mengetahui jawabannya sendiri: apakah akan memanggil metode berikut atau tidak (dan ini membutuhkan setidaknya beberapa jenis pengikatan pada konfigurasi umum). Karena skema kerja ini, Memori Habis digunakan oleh saya pada sebagian besar tes (jika saya menggunakan jalur yang berbeda, dll.).
• LogManager.GetCurrentClassLogger() bahkan lebih lambat dari LogManager.GetLogget(typeof(XXX)) . Ini logis, bahkan pengembang NLog tidak menyarankan memanggil metode pertama dalam satu lingkaran.
• Dan yang paling penting: kecepatan semua metode ini sering hanya mempengaruhi awal yang dingin dari aplikasi ketika bidang bentuk private static readonly ILogger Log = LogManager.GetCurrentClassLogger() . Artinya, itu tidak secara langsung mempengaruhi kinerja sistem.

Kesimpulan

Apa cara terbaik untuk menangani log:

• Jika mungkin untuk tidak login sama sekali, ini akan menjadi yang tercepat (yang sudah jelas sejauh ini).
• Jika proyek memiliki banyak panggilan logger yang tidak membuang data ke file (ke konsol, dll.), Maka NLog lebih cepat. Selain itu, ia mengalokasikan lebih sedikit objek di heap.
• Jika Anda masih perlu menulis ke file, maka NLog bekerja secara asinkron dengan paling cepat. Ya, itu memakan lebih banyak memori (dibandingkan dengan NLog dalam mode sinkron, karena menurut pengukuran saya sebelumnya, log4net bahkan tidak mencoba untuk menggunakan kembali array dan Stream 's. Namun, program akan dapat berjalan lebih cepat.
• Membuat logger bukan operasi gratis, jadi seringkali lebih baik untuk membuatnya dengan bidang statis. Ini tidak berlaku untuk membuat dari string, yaitu sesuatu seperti LogManager.GetLogger("123") . Panggilan semacam itu bekerja lebih cepat, yang berarti bahwa logger dapat dibuat untuk instance objek yang besar (misalnya, "satu logger untuk konteks kueri").
• Jika Anda ingin menampilkan banyak parameter ke log, tetapi dalam kebanyakan kasus tidak akan ada data dump langsung ke file, yang terbaik adalah membuat beberapa panggilan. Oleh karena itu, NLog tidak akan membuat objek tambahan di heap jika mereka tidak diperlukan di sana.

Kesimpulan untuk kode Anda:

• Jika metode Anda menerima objek sewenang-wenang (mis. object ) dan dalam kebanyakan kasus tidak melakukan apa-apa (yang berlaku untuk kontrak / validator), maka paling benar untuk membungkus panggilan dalam bentuk generik (mis. Membuat metode dalam bentuk Something<TArg>(TArg arg) ). Ini akan bekerja sangat cepat.
• Jika dalam kode Anda reset data file diperbolehkan dan pada saat yang sama bekerja dengan sesuatu yang lain, lebih baik untuk menjadi bingung dan mendukung ini. Ya, tampak jelas bahwa eksekusi paralel dapat mempercepat pekerjaan, namun, dalam kasus operasi IO, pendekatan ini juga memberikan peningkatan kinerja tambahan pada mesin dengan disk yang lambat.