Ich habe eine Client-Software, die einen Apache-HTTPD-Server aufruft, auf derselben Maschine installiert. Vor dem Aufruf protokolliert Apache einen Protokolleintrag:
2011-11-23 13:27:43,777 | 8323|1381677376 | root | DEBUG | Calling http://mydomain.com/api/project/325/postings/add_and_remove_labels
Wie Sie sehen, erfolgt der Anruf um 13:27:43 Uhr Ortszeit. Die Domäne mydomain.com löst die externe IP derselben Maschine auf.
Wenn ich mir jedoch die Datei access.log anschaue, sehe ich einen Logeintrag, dessen Zeitstempel[1] 5 Sekunden später liegt:
[23/Nov/2011:13:27:48 +0100] "GET /api/project/325/postings/add_and_remove_labels
Dies ist ein mod_wsgi-Basisserver, der im Daemon-Modus ausgeführt wird, aber ich bin nicht sicher, ob dies relevant ist (der Zeitstempel sollte der Beginn der Anforderung auf Apache-Ebene sein).
Wie gehe ich am besten vor, um die Quelle dieser 5 Sekunden herauszufinden?
Grüße, Boaz
Erläuterung: [1] - Der Zeitstempel gibt an, wann die Anfragegestartet. Es stimmt, dass der Eintrag in das Protokoll geschrieben wird, wenn die Anfrage endet, aber die Zeit ist die des Anfragestarts.
Antwort1
Dies liegt daran, dass das Zugriffsprotokoll an derEndeder Anfrage, nicht der Anfang. Wenn Sie die Anfrage also um 12:00 Uhr stellen und es eine Minute dauert, bis sie abgeschlossen ist, wird der Eintrag erst um 12:01 Uhr geschrieben. Die Tatsache, dass er Dinge wie die Anzahl der übertragenen Bytes enthalten kann, ist ein sicherer Indikator dafür.
Sie können auch einen Traceroute von einem Host zum anderen ausführen, um zu prüfen, ob die Anforderung tatsächlich eingeht. Wenn beim Routing Verzögerungen auftreten, haben Sie die Ursache Ihres Problems gefunden.
Antwort2
Zwei Dinge, die Sie überprüfen sollten:
- die Zeit, die zum Auflösen des Namens mydomain.com auf dem Server benötigt wird (Mitteilung an TokenMacGuy in den Kommentaren)
- die Ausführungszeit Ihres Skripts, da das Protokoll nach Abschluss der Anfrage geschrieben wird