Halo, Habr!
Saya pikir hampir setiap program memiliki pencatatan. Selain itu, di sejumlah aplikasi yang sudah baru (yang berarti dengan kondisi laut nontrivial), log sering menjadi vital di server tempur.
Namun, terlepas dari pentingnya dan prevalensi teknologi semacam itu, saya perhatikan bahwa orang sering membuat kesalahan standar ketika bekerja dengan mereka. Artikel ini menjelaskan perilaku. Net dalam banyak hal, namun, saya membuat sisipan kecil dari dunia Jawa, hanya untuk perbandingan.
Alokasi (alokasi memori)
Kesalahan paling umum (menurut pengamatan saya) adalah kelalaian dalam kaitannya dengan alokasi memori kecil di dekat tempat panggilan ke fungsi log.Debug(...) .
Jadi, kode standar kami di .Net:
private static readonly ILog Log4NetLog = LogManager.GetLogger(typeof(Program)); private static readonly Logger NLogLog = NLog.LogManager.GetCurrentClassLogger(); private static void PublishData(int id, string name, EMail email, decimal amount) { Log4NetLog.Debug($"Id={id}"); // 1 Log4NetLog.DebugFormat("Id={0}", id); // 2 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 NLogLog.Debug($"Id={id}"); // 5 NLogLog.Debug("Id={0}", id); // 6 NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 7 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 8 }
Dalam banyak hal, saya hanya melihat perpustakaan log4net dan NLog , dan karena itu saya akan menggunakannya dalam contoh.
Jadi pertanyaannya adalah:
- Di baris mana memori akan dialokasikan bahkan jika Debug dimatikan?
- Jika memori dialokasikan, seberapa mudahnya untuk mendeteksi dalam dotTrace yang sama yang secara khusus dipersalahkan oleh para penebang karena alokasi memori ini?
Jawaban yang benar untuk pertanyaan pertama: memori tidak hanya dialokasikan dalam paragraf "6". Dan jawaban untuk pertanyaan kedua: sangat sulit ditangkap, karena kode seperti itu sering tersebar di proyek. Anda mungkin mengingat aplikasi .Net yang khas. Sering kali akan memiliki kode serupa yang membuat GC berfungsi.
Namun, mari kita lihat detail teknis untuk memahami dengan tepat di mana kita akan berdampak pada kinerja.
Jadi poin pertama:
Log4NetLog.Debug($"Id={id}"); // 1
Faktanya, kompiler akan mengubahnya menjadi:
var temp = string.Format("Id={0}", id); // <-- Log4NetLog.Debug(temp);
Artinya, ekspresi pertama pada dasarnya akan memaksa prosesor untuk membuat string, meneruskannya ke logger. Dia akan dengan cepat memeriksa bahwa Anda tidak perlu login, dan oleh karena itu baris baru saja dibuat di memori. Dan, yang penting, jika Anda menyalin lebih banyak kode seperti itu, maka baris akan dibuat di banyak tempat program, yaitu, program akan bekerja sedikit lebih lambat. Di mana-mana.
Contoh kedua sedikit lebih efisien, karena baris tidak dibuat di dalamnya:
Log4NetLog.DebugFormat("Id={0}", id);
Namun, memori masih dialokasikan di sini, karena tinju akan terjadi. Biarkan saya mengingatkan Anda tanda tangan dari metode DebugFormat:
void DebugFormat(string format, object arg0)
Seperti yang Anda lihat, input membutuhkan tipe referensi. Namun, kami mencoba untuk melewati tipe int berarti. Akibatnya, setiap panggilan akan menghasilkan id parameter tumpukan yang diteruskan untuk meneruskannya ke metode. Dan izinkan saya mengingatkan Anda bahwa parameter itu sendiri tidak diperlukan dalam metode itu sendiri, karena Debug dimatikan oleh kondisi tugas.
Contoh berikut ini dimuat dan sederhana:
Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3
Saya yakin Anda sudah mengerti bahwa sekali lagi garis akan menonjol di tumpukan dan seterusnya. Karena itu, segera lewati contoh ini. Metode panggilan berikut terlihat lebih efisien:
Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4
Namun demikian, mari kita hitung berapa kali perlu mengalokasikan sepotong memori:
email.Normalize() mengarah ke pembuatan beberapa jenis objek. Oleh karena itu, objek ini akan dialokasikan pada heap (atau pada stack - itu tidak masalah, karena tinju akan membuatnya perlu untuk memilih semua yang ada di heap)id akan menuju heap, seperti yang sudah kita bahas sebelumnya.- Log4net memiliki antarmuka berikut untuk panggilan panjang yang diformat:
void DebugFormat(string format, params object[] args) . Seperti yang Anda lihat, .Net akan membuat array di heap untuk meneruskannya ke metode DebugFormat .
Akibatnya, panggilan yang cukup tipikal untuk operasi logging akan mengarah pada penciptaan tumpukan objek dalam memori. Yang agak mengecewakan, karena logging itu sendiri sering dimatikan. Namun, mari kita beralih ke NLog.
Baris ini akan memancing alokasi objek pada heap:
NLogLog.Debug($"Id={id}");
Semuanya jelas di sini, tetapi garis di bawah tidak lagi memiliki kelemahan seperti itu:
NLogLog.Debug("Id={0}", id);
Dan alasannya adalah NLog memiliki tanda tangan khusus untuk ints: void Debug(string message, int argument) . Selain itu, bahkan jika Anda mentransfer struktur yang berbeda, metode void Debug<TArgument>([Localizable(false)] string message, TArgument argument) . Dan metode ini tidak memerlukan tinju, karena setelah JIT fungsi terpisah akan dibuat untuk setiap jenis (tentu saja, ini tidak sepenuhnya benar, tetapi poin pentingnya adalah: tidak akan ada tinju).
Saya akan melewati skrip yang mudah dipahami dengan jalur input besar dan langsung ke:
NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount);
Anehnya, NLog tidak menambah jumlah parameter Generik untuk metode, dan oleh karena itu tanda tangan akan digunakan: void Debug([Localizable(false)] string message, params object[] args) . Dan itu lagi akan mengarah pada penciptaan objek di tumpukan dan seterusnya.
Kesimpulan dan Perbaikan
Kesimpulan utama: jika Anda memiliki banyak panggilan ke metode logging di program yang tidak mengarah ke penulisan fisik ke file, maka Anda bisa tiba-tiba mulai mengalokasikan banyak objek yang tidak perlu pada heap. Dan dengan demikian menghambat kerja program.
Kesimpulan 2: Jika Anda melewatkan tidak banyak objek ke suatu metode, gunakan NLog. Karena faktanya memperhatikan parameter Generic, Anda bisa lebih santai tentang kinerjanya.
Namun, agar benar-benar aman, lebih logis untuk melakukan ini:
if (NLogLog.IsDebugEnabled) { NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); }
Di sini metode logging tidak akan dipanggil jika tidak perlu. Namun, jika Anda masih harus membuang data ke log, maka Interpolasi String yang nyaman akan digunakan. Di dalam, logger (setidaknya NLog yang sama) memiliki optimisasi untuk menulis baris ke log secara langsung (mis. Pemformatan akan muncul segera di Stream , alih-alih membuat garis dalam memori). Namun, pengoptimalan NLog ini memudar dengan fakta bahwa Anda harus mengatur ulang data ke file.
Contoh Kotlin
Untuk mencairkan deskripsi karya para penebang populer di .Net, saya akan memberikan cara yang menarik untuk melakukan panggilan di kotlin. Idenya didasarkan pada satu fitur bahasa yang menarik: metode inline . Jadi, kode sederhana untuk mengeluarkan sesuatu ke debug:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { "Identity: $id" } } }
Dan itu akan dikonversi oleh kompiler menjadi sesuatu seperti ini:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val message = "Identity: $id" logger.debug(message) }catch (e: Exception){ } } } }
Ini penting di sini: semua yang ada di dalam kawat gigi dekat debug adalah lambda. Namun, itu akan tertanam dalam metode Anda, yaitu, objek fungsi tidak akan dibuat di heap. Dengan demikian, Anda dapat menyembunyikan operasi besar di dalam, yang akan dipanggil hanya jika Anda ingin menampilkan hasilnya ke debug . Sebagai contoh:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { val idList = getIdList() "Identity: $idList" } } }
Di sini getIdList akan dipanggil hanya jika Anda perlu mengirim sesuatu ke file. Dan semua itu karena kode tersebut dikonversi menjadi:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val idList = getIdList() val message = "Identity: $idList" logger.debug(message) }catch (){ } } logger.debug { "Identity: $id" } } }
Obyek Besar ==> Tumpukan Objek Besar
Selain contoh sebelumnya. Saya yakin banyak orang tahu bahwa .Net / JVM memiliki konsep "Large Object Heap". Lebih tepatnya, tidak ada definisi khusus di Jawa, namun, pengalokasi akan sering membuat objek besar segera di generasi terbaru (untuk meminimalkan pergerakan objek dan meratakan masalah penetrasi memori cepat untuk pengalokasi streaming).
Kembali ke contoh:
NLogLog.Debug($"Id={id}");
Seperti yang Anda pahami, jika objek id memiliki implementasi ToString , yang membuat string seukuran megabyte, maka klik berikut di wajah LOH:
- Panggilan
ToString sendiri - Memformat
$"Id={id}" - Dan jika pengembang logger tidak menangkap semua hal ini (dan sangat sulit untuk menulis tes untuk ketiadaan objek di LOH), maka logger akan menambah masalah.
Dan di sini Anda dapat menggunakan tiga metode logging hal-hal seperti:
- Gunakan tata letak khusus dan tidak memerlukan panggilan ke
ToString . Misalnya, NLog memiliki JsonLayout . Dengan demikian, Anda dapat dengan mudah mentransfer objek ke logger, yang akan segera diserialisasi ke aliran yang dihasilkan (misalnya, ke file). - Tulis sendiri ke file. Atau dengan kata lain - jangan gunakan logger. Saya hanya bisa memberi saran tentang bagaimana saya mencari tahu file NLog mana yang akan menulis:
var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()) . Jelas, fungsi ini akan mengembalikan FileTarget pertama yang muncul, tetapi jika semua orang menulis ke folder yang sama, dengan cara yang sama Anda dapat mengetahui folder untuk direkam, dan kemudian langsung mengirim dump objek Anda ke file. - Jika Anda memiliki log4j2 (yang kedua penting), maka Anda dapat menggunakan StringBuilderFormattable . Itu baru saja dibuat untuk menampilkan data ke dalam logger dalam potongan-potongan (apalagi, agar tidak mengalokasikan bagian dari potongan-potongan di tumpukan, karena mereka sudah dipilih).
public interface StringBuilderFormattable { void formatTo(StringBuilder buffer); }
Sinkronisasi (dan masalah sinkronisasi)
Suatu ketika, dalam satu program, saya perhatikan bahwa selama operasi yang dimuat, sekitar setengah waktu tunggu UI dicatat oleh operasi logging. Sekali lagi: setengah dari waktu program dihabiskan untuk panggilan ke logger.Debug atau sesuatu seperti itu. Dan alasannya sederhana: kami menggunakan log4net, yang hanya dapat menulis file secara sinkron.
Dari sini saya menyimpulkan aturan 1 : logger harus selalu bekerja di utas lainnya. Anda tidak boleh memblokir kode aplikasi demi jejak, karena ini sangat aneh. Dengan kata lain - menggunakan NLog - Anda selalu harus memasukkan async=true di tag nlog (ini yang utama). Atau, seperti contohnya :
<targets async="true"> ... your targets go here ... </targets>
Jika Anda menggunakan log4net, maka arahkan dari NLog, atau buat AsyncFileAppender.
Untuk dunia Java: Logback dan Log4J2 memiliki kemampuan untuk melakukan logging asinkron. Berikut ini adalah perbandingan dari situs resmi :
Namun, ketika semuanya ditulis secara tidak sinkron, muncul masalah lain - apa yang harus dilakukan jika terjadi kesalahan kritis? Setelah semua, itu terjadi bahwa suatu program tidak keluar karena telah meninggalkan utas Main (misalnya, suatu program dapat keluar dengan memanggil Application.Exit atau Environment.FailFast , yang tidak terlalu indah, tetapi memang terjadi). Dalam hal ini, Anda harus selalu memanggil Flush sebelum mematikan proses Anda. Kalau tidak, jika Anda jatuh di server pertempuran, informasi yang paling berharga akan terlewatkan.
Kesimpulan
Saya harap artikel ini membantu Anda menulis program cepat dengan pencatatan yang nyaman. Saya menyoroti hanya sebagian dari masalah yang saya lihat bagian dalam kode. Semuanya bukan yang paling jelas, tetapi bukan yang paling sulit.
Bagaimanapun, seperti yang saya katakan di awal, bekerja dengan penebang hampir di setiap aplikasi. Selain itu, menurut catatan saya, sekitar setengah dari kelas itu sendiri mengeluarkan sesuatu ke log. Dengan demikian, operasi yang benar dengan fungsi-fungsi ini mempengaruhi hampir seluruh aplikasi.