Last active
December 18, 2015 05:09
-
-
Save pcn/5730279 to your computer and use it in GitHub Desktop.
Relay sending code that logs timestamps
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| def _sendDatapoints(self, datapoints): | |
| # XXX: Make this a logging option | |
| # log to the oldest and newest datapoint in the pickle | |
| # looks like ('Platform2.Wonderwoman.RecommendationService.i-8ecebae0.internal.actors.total-dirty-keys-since-restart.InstructionAtomicKankoku.gauge.value', (137061\ | |
| 9773.0, 58297.0)) | |
| def datapoint_timestamp(point): | |
| return point[1][0] | |
| now = time() | |
| my_max = max(datapoints, key=datapoint_timestamp) | |
| my_min = min(datapoints, key=datapoint_timestamp) | |
| print "At {0} batch oldest: {1} (difference of {2})".format(now, my_min, now - datapoint_timestamp(my_min)) | |
| print "At {0} batch newest: {1} (difference of {2})".format(now, my_max, now - datapoint_timestamp(my_max)) | |
| if now - datapoint_timestamp(my_min) > 60: | |
| print "WARNING batch oldest is >60 seconds old" | |
| self.sendString(pickle.dumps(datapoints, protocol=-1)) | |
| instrumentation.increment(self.sent, len(datapoints)) | |
| instrumentation.increment(self.batchesSent) | |
| self.factory.checkQueue() |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| We may have a cause now. It looks like this system, which isn't terribly busy, isn't getting the CPU cycles that it should: | |
| ``` | |
| pn@ip-10-250-134-160:~$ mpstat 1 | |
| Linux 2.6.38-11-virtual (ip-10-250-134-160) 06/09/2013 _x86_64_ (2 CPU) | |
| 01:35:21 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %idle | |
| 01:35:22 AM all 27.52 0.00 2.35 0.00 0.00 0.67 10.40 0.00 59.06 | |
| 01:35:23 AM all 29.15 0.00 1.36 0.00 0.00 0.34 8.14 0.00 61.02 | |
| 01:35:24 AM all 28.14 0.00 2.71 0.00 0.00 0.00 8.14 0.00 61.02 | |
| 01:35:25 AM all 28.09 0.00 2.34 0.00 0.00 0.00 8.36 0.00 61.20 | |
| 01:35:26 AM all 25.91 0.00 1.00 0.00 0.00 0.00 8.31 0.00 64.78 | |
| 01:35:27 AM all 25.95 0.00 3.81 0.00 0.00 0.00 8.30 0.00 61.94 | |
| 01:35:28 AM all 10.99 0.00 1.65 0.00 0.00 0.27 0.00 0.00 87.09 | |
| 01:35:29 AM all 16.67 0.00 0.91 0.00 0.00 0.30 1.82 0.00 80.30 | |
| 01:35:30 AM all 21.10 0.00 0.92 0.00 0.00 1.22 3.67 0.00 73.09 | |
| 01:35:31 AM all 27.15 0.00 2.75 0.00 0.00 0.00 8.93 0.00 61.17 | |
| 01:35:32 AM all 28.57 0.00 4.18 0.00 0.00 0.00 6.27 0.00 60.98 | |
| 01:35:33 AM all 11.01 0.00 5.50 0.00 0.00 0.31 3.67 0.00 79.51 | |
| 01:35:34 AM all 22.53 0.00 3.09 0.00 0.00 1.23 3.70 0.00 69.44 | |
| 01:35:36 AM all 19.64 0.00 0.91 0.00 0.00 1.81 7.25 0.00 70.39 | |
| 01:35:37 AM all 21.50 0.00 1.63 0.00 0.00 3.58 6.19 0.00 67.10 | |
| 01:35:38 AM all 25.09 0.00 4.53 0.00 0.00 1.05 6.27 0.00 63.07 | |
| 01:35:39 AM all 23.38 0.00 1.95 0.00 0.00 0.97 2.27 0.00 71.43 | |
| ``` | |
| Notice that the "steal" time is almost never 0? That's terrible and... maybe it would explain why data isn't getting sent. If the steal time is happening when twisted is trying to flush the network... maybe that causes a backoff or some other slowdown. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| For reference, our other relay, which doesn't do quite as much work as our main relay looks like this: | |
| ``` | |
| pn@ip-10-250-131-68:~$ mpstat 1 | |
| Linux 2.6.38-11-virtual (ip-10-250-131-68) 06/09/2013 _x86_64_ (2 CPU) | |
| 01:40:08 AM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %idle | |
| 01:40:09 AM all 4.17 0.00 0.26 0.00 0.00 0.00 0.00 0.00 95.57 | |
| 01:40:10 AM all 3.39 0.00 0.00 0.00 0.00 0.00 0.00 0.00 96.61 | |
| 01:40:11 AM all 11.30 0.00 0.28 0.00 0.00 0.00 1.69 0.00 86.72 | |
| 01:40:12 AM all 3.93 0.00 0.26 0.00 0.00 0.00 0.00 0.00 95.81 | |
| 01:40:13 AM all 5.26 0.00 0.00 0.00 0.00 0.00 0.00 0.00 94.74 | |
| 01:40:14 AM all 2.56 0.00 0.00 0.00 0.00 0.00 0.00 0.00 97.44 | |
| 01:40:15 AM all 2.82 0.00 0.00 0.00 0.00 0.00 0.00 0.00 97.18 | |
| 01:40:16 AM all 2.02 0.00 0.00 0.00 0.00 0.00 0.00 0.00 97.98 | |
| 01:40:17 AM all 2.31 0.00 0.00 0.00 0.00 0.00 0.00 0.00 97.69 | |
| 01:40:18 AM all 3.39 0.00 0.26 0.00 0.00 0.00 0.00 0.00 96.35 | |
| 01:40:19 AM all 10.03 0.00 0.00 0.00 0.00 0.00 0.00 0.00 89.97 | |
| 01:40:20 AM all 28.82 0.00 0.00 0.00 0.00 0.00 2.08 0.00 69.10 | |
| 01:40:21 AM all 28.53 0.00 0.32 0.00 0.00 0.00 13.46 0.00 57.69 | |
| ``` | |
| This one clearly has a lot more run time available to it, and it does seem to have steal time happening. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| pn@ip-10-250-134-160:/opt/graphite/lib/carbon$ for count in $(seq 30) ; do date; netstat -an | grep 78.46.93.167:2004; sleep 5 | |
| > done | |
| Fri Jun 7 21:21:07 UTC 2013 | |
| tcp 0 0 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:12 UTC 2013 | |
| tcp 0 48536 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:17 UTC 2013 | |
| tcp 0 129624 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:22 UTC 2013 | |
| tcp 0 134192 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:27 UTC 2013 | |
| tcp 0 197680 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:32 UTC 2013 | |
| tcp 0 0 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:37 UTC 2013 | |
| tcp 0 29712 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:43 UTC 2013 | |
| tcp 0 52880 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:48 UTC 2013 | |
| tcp 0 225888 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:53 UTC 2013 | |
| tcp 0 233128 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:21:58 UTC 2013 | |
| tcp 0 196984 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:22:03 UTC 2013 | |
| tcp 0 260640 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:22:08 UTC 2013 | |
| tcp 0 54328 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:22:13 UTC 2013 | |
| tcp 0 186152 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:22:18 UTC 2013 | |
| tcp 0 274480 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED | |
| Fri Jun 7 21:22:23 UTC 2013 | |
| tcp 0 240368 10.250.134.160:56746 78.46.93.167:2004 ESTABLISHED |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| When the above function is being used, the log shows a very short time between timestamp, and the data being written to the twisted connected protocol. | |
| However, the delay continues to be present. To try to better identify what's going on, I'm sending hostedgraphite a bogus counter - a timestamp that I'm adding to every pickle - every send - that contains the current time as both the time field and the value. | |
| To examine this, I'm looking at the time according to libpcap (I believe it's the library) vs. the time in the packet, and this is what I'm seeing: | |
| ``` | |
| T 2013/06/09 00:53:52.819385 10.250.134.160:37673 -> 78.46.93.167:2004 [A] | |
| 4e 6f 6e 2d 6d 61 73 6b 61 62 6c 65 5f 69 6e 74 Non-maskable_int | |
| 65 72 72 75 70 74 73 2e 74 6f 74 61 6c 47 41 d4 errupts.totalGA. | |
| -- | |
| 5d 71 01 28 55 14 6b 6e 65 77 74 6f 6e 2e 68 67 ]q.(U.knewton.hg | |
| 2e 74 69 6d 65 73 74 61 6d 70 71 02 47 41 d4 6c .timestampq.GA.l | |
| f4 28 e3 bd b2 47 41 d4 6c f4 28 e3 bd b2 86 86 .(...GA.l.(..... | |
| ``` | |
| The key point is that while the capture says that the package was from "2013/06/09 00:53:52.819385", the timestamp in the knewton.hg.timestamp metric is this: | |
| ``` | |
| Sun Jun 9 00:47:31 2013 | |
| ``` | |
| That's a whole 6 minutes old! | |
| The above packet capture is from running this command: | |
| ``` | |
| sudo ngrep -x -t 'knewton\.hg' 'host 78.46.93.167' | egrep -A2 'knewton.hg|^T ' | |
| ``` | |
| and the date in the stat is gotten from that output. Knowing a bit about the python pickle format shows that the 8 byte float that is the date is the characters "41 d4 6c < next line > f4 28 e3 bd b2". That can be turned from 8 bytes in network byte order into a date by doing this: | |
| ```python | |
| from time import ctime | |
| from struct import unpack | |
| ctime(unpack('!d', '\x41\xd4\x6c\xf4\x28\xe3\xbd\xb2')[0]) | |
| ``` | |
| So the data we're sending to hosted graphite is indeed accumulating inside the carbon-cache, inside twisted, somewhere in the connected protocol or below that in the stack. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment