Ήμουν στη δουλειά πριν λίγο καιρό, κι αναρωτιόμουν ... πόσο χρόνο μου παίρνει το κάθε επιμέρους task που πρέπει να εκτελώ, για να δείξω τελικά το αποτέλεσμα της σελίδας μου;
Φαντάζομαι ότι δεν είμαι πρωτότυπος σ' αυτό. Απλώς στο project στο οποίο εργάζομαι αυτή τη στιγμή .. δεν έχω βάση δεδομένων. Φτιάχνουμε το front-end, πάνω άπο κάποια services τα οποία μας επιστρέφουν xml. Πoλλή xml, της τάξεως των 40 - 50k per call. Όλα αυτά γίνονται deserialize σε ένα object tree, και bind τελικά στη σελίδα μου βάσει κανόνων και dependencies.
Οπότε κάποια στιγμή άρχισα όντως να σκέφτομαι, ότι οκ, φαίνονται όλα καλά με τους 2-3 χρήστες στο εκάστοτε development μηχάνημα, αλλά .. τί "πονάει" περισότερο απο όλα αυτά; ποιό είναι το μέρος το οποίο θα μας πονέσει ακόμη περισσότερο αργότερα;
Αποφάσισα λοιπόν να κάνω κάποιες μετρήσεις ... και άρχισα με ένα System.Diagnostics.Stopwatch. Πολύ σύντομα όμως, βαρέθηκα να γράφω τον ίδιο κώδικα σε ένα κάρο μέρη στον κώδικά μου, χαλώντας και τον κώδικα στην τελική, και το readability που μπορεί να είχε. Οπότε στο πίσω μέρος του μυαλού μου, μου είχε μείνει αυτή η .. αναζήτηση επι ματαίω :D
Ευτυχώς - για 'μένα τουλάχιστον - το project το γράφουμε σε .NET 3.5 και C#. Οπότε, με τα νέα καλούδια της γλώσσας κάποια στιγμή μου ήρθε η επιφοίτηση και λέω .. "
ρε φίλε, αν περάσω ένα lambda - anonymous method σε κάτι ... τότε δε θα μπορέσω μια χαρά να μετράω το execution time του, και να το καταγράφω κάπου εύκολα και όμορφα;"
Φυσικά, και σε .NET 2.0 θα μπορούσες να το κάνεις αυτό - απλώς εγώ είχα την ευτυχία ή δυστυχία να περάσω με τη μια απο 1.1 σε 3.5, ε, και σε 3.5 είναι και πιο όμορφο ρε παιδί μου :D
Ξεκινάω λοιπόν να δώ τι και πώς ...
// <summary>
/// No params, void return
/// </summary>
/// <param name="logMessage"></param>
/// <param
name="noParamReturnVoid"></param>
public static void MeasureTime(string
logMessage, Action noParamReturnVoid) {
Stopwatch watch = new
Stopwatch();
watch.Start();
try {
noParamReturnVoid();
}
finally {
watch.Stop();
Logger.Log("Timed
{0} at {1} millis", logMessage, watch.ElapsedMilliseconds);
}
}
Ωραίο, μικρό και χαριτωμένο ... το Action είναι ένας ειδικός delgate type, που υποδηλώνει μέθοδο η οποία δε δέχεται παραμέτρους, και δεν επιστρέφει τίποτα. Έχει και generic αδερφάκι, στο οποίο δηλώνεις με generic parameters μεθόδους οι οποίες δέχονται παραμέτρους, αλλά και πάλι δεν επιστρέφουν τιμή, είναι void.
Με τα πολλά, έφτασα να γράψω overloads για μέχρι και 3 παραμέτρους ...
/// <summary>
/// 3 params, void return
/// </summary>
public static void MeasureTime<TParam1, TParam2, TParam3,
TRetType>(string logMessage, Action<TParam1, TParam2, TParam3>
threeParamReturnVoid, TParam1 p1, TParam2 p2, TParam3 p3) {
Stopwatch watch = new
Stopwatch();
watch.Start();
try {
threeParamReturnVoid(p1, p2, p3);
}
finally {
watch.Stop();
Logger.Log("Timed
{0} at {1} millis", logMessage, watch.ElapsedMilliseconds);
}
}
Η "ομορφιά" αυτού του πράγματος, κατα την ταπεινή μου γνώμη, είναι ότι κάνει "inject" functionality - το ότι μετράω το χρόνο και log-άρω εν προκειμένω - τελείως "διάφανα". Π.χ. ... αν σκάσει στη μέση του lambda ένα exception, θα γίνει bubble κανονικά, δε χρειάζεται να αλλάξω τον κώδικά μου σχεδόν καθόλου. Κι ακόμη και η αλλαγή που θα του κάνω, μπορεί να είναι τελείως minimal, π.χ. ...
private static TRetType
DeserializeInto<TRetType>(string
xmlString) {
using (StringReader
reader = new StringReader(xmlString))
{
return (TRetType)(new
XmlSerializer(typeof(TRetType))).Deserialize(reader);
}
}
.. θα γίνει ...
private static TRetType
DeserializeInto<TRetType>(string
xmlString) {
// Measure and return ...
return ExecutionTimer.MeasureTime(String.Format("Deserialize
into: {0}", typeof(TRetType)), ()
=> {
using (StringReader
reader = new StringReader(xmlString))
{
return (TRetType)(new
XmlSerializer(typeof(TRetType))).Deserialize(reader);
}
});
}
.. ο "
μετά" κώδικας, διαβάζεται εξίσου εύκολα με τον αρχικό. Αν το κοιτάξεις στα γρήγορα ίσως δεν προσέξεις κάν ότι γίνεται όλη αυτή η ιστορία.
Στο παραδειγματάκι τούτο 'δω, χρησιμοποιώ ακόμα ένα overload, που πλέον το lambda που θα περάσω στον ExecutionTimer επιστρέφει τιμή. ¨εγραψα και πάλι overloads και για αυτό το pattern απο 0 ως 3 παραμέτρους
/// <summary>
/// No params, TRetType
return
/// </summary>
/// <typeparam
name="TRetType"></typeparam>
/// <param name="logMessage"></param>
/// <param
name="noParamReturnTRetType"></param>
/// <returns></returns>
public static
TRetType MeasureTime<TRetType>(string
logMessage, Func<TRetType>
noParamReturnTRetType) {
Stopwatch watch = new
Stopwatch();
watch.Start();
try {
return noParamReturnTRetType();
}
finally {
watch.Stop();
Logger.Log("Timed
{0} at {1} millis", logMessage, watch.ElapsedMilliseconds);
}
}
.. μέχρι και ...
/// <summary>
/// 3 params, TRetType
return
/// </summary>
public static
TRetType MeasureTime<TParam1, TParam2, TParam3, TRetType>(string logMessage, Func<TParam1,
TParam2, TParam3, TRetType> threeParamReturnTRetType, TParam1 p1, TParam2
p2, TParam3 p3) {
Stopwatch watch = new
Stopwatch();
watch.Start();
try {
return threeParamReturnTRetType(p1, p2, p3);
}
finally {
watch.Stop();
Logger.Log("Timed
{0} at {1} millis", logMessage, watch.ElapsedMilliseconds);
}
}
.. 'ντάξει ... τίποτα σπουδαίο, αλλά ταυτόχρονα σπουδαίο κιόλας ! :D ... γιατι μου έλυσε τα χέρια σε 20 λεπτάκια, και σε μια ώρα είχα time stats per request άνετα και χαλαρά. Τα 'βαλα μέσα στην κλασσούλα τους, τον ExecutionTimer, και έγραψα κι έναν ψιλό-gay Logger ... σούπερ.
Ο μικρός Logger, απλώς σώζει ένα LogEntry : List<string> στο HttpContext.Items του κάθε Request μου, κι έτσι μπορώ να το βρίσκω απο τις static μεθόδους του, τη Log(...) στο παράδειγμα πιο πάνω.
Το ίδιο το LogEntry, έχει κι αυτό ένα Stopwatch μέσα του, για να μετράω το συνολικό χρόνο του Request - κάποια στιγμή με βοήθησε αυτό να βρώ αποκλίσεις, u know, τα νουμεράκια για τις επιμέρους κλίσεις δε μου αθρολιζονταν σωστά / λογικά σε σχέση με το σύνολο του LogEntry, άρα κάπου είχα ξεχάσει μετρήσεις κτλ κτλ ...
Κατα τ'άλλα, μέσα στο Global.asax - ή μάλλον σε μια κλάσση ξεχωριστή, την οποία έκανα inherit στο Global.asax - σε κάθε Begin & End Request φτιάχνω ένα LogEntry, και στο End το γράφω σα div-άκι στη σελίδα μου, για να βλέπω τι μέτρησε και χρόνους ...
void Request_Start(object sender,
EventArgs e) {
// Start a new Log Entry ...
Logger.BeginLogEntry();
}
void Request_End(object
sender, EventArgs e) {
// Get the Log Entry, now filled with log messages ...
Response.Write(Logger.EndLogEntry().ToString());
}
Attached στο post, έχω τα sources απο ένα μικρό sample που έγραψα, για να μετρήσω ποσό κάνει ένα read απο αρχείο και deserialize απο xml σε objects ένα αρκετά μεγάλο xml, προσομοιώνοντας και καλά ένα web service call. Όχι κάτι σπουδαίο, αλλά δίνει μια ιδέα. Αν κάποιος το βρεί χρήσιμο και το χρησιμοποιήσει, θα με κάνει ένα πολύ χαρούμενο anjeliniο :)
Πολύ καλός Πάσχας μας λοιπόν !
Angel
O:]