{"id":3216,"date":"2014-04-14T13:11:27","date_gmt":"2014-04-14T12:11:27","guid":{"rendered":"http:\/\/t-machine.org\/?p=3216"},"modified":"2014-04-14T13:12:13","modified_gmt":"2014-04-14T12:12:13","slug":"debugging-odd-problems-when-writing-game-servers","status":"publish","type":"post","link":"http:\/\/new.t-machine.org\/index.php\/2014\/04\/14\/debugging-odd-problems-when-writing-game-servers\/","title":{"rendered":"Debugging odd problems when writing game servers"},"content":{"rendered":"

Cas (@PuppyGames)<\/a> (of PuppyGames fame – Titan Attacks<\/a>, Revenge of the Titans<\/a>, etc) is working on an awesome new MMO RTS … thing.<\/p>\n

He had a weird networking problem, and was looking for suggestions on possible causes. I used to do a lot of MMO dev, so we ran through the “typical” problems. This isn’t exhaustive, but as a quick-n-dirty checklist, I figured it could help some other indie gamedevs doing multiplayer\/network code.<\/p>\n

Scenario<\/h2>\n
    \n
  1. Java, Windows 7\n
  2. DataInputStream.readFully() from a socket… a local socket at that… taking 4.5 seconds to read the first bytes\n
  3. and I’ve already read a few bits and bobs out of it\n<\/ol>\n

    Initial thoughts<\/h2>\n

    First thought: in networking, everything has a realm of durations. The speed of light means that a network connection from New York to London takes a few milliseconds (unavoidably) – everything is measured in ms, unless you’re on a local machine, in which case: the OS internally works in microseconds (almost too small to measure). Since Cas’s problem is measured in SECONDS – but is on localhost – it’s probably something external to the OS, external to the networking itself.<\/p>\n

    Gut feel would be something like Nagle’s algorithm, although I’m sure everyone’s already configured that appropriately ;).<\/p>\n

    That, or a routing table that’s changing dynamically – e.g. first packet is triggering a “let me start the dialup connection for you”, causing everything to pause (note that “4 seconds” is in the realm of time it takes for modems to connect; it’s outside the realm of ethernet delays, as already noted)<\/p>\n

    My general advice for “bizarre server-networking bugs”: start doing the things you know are “wrong” from a performance view, and prove that each makes it worse. If one does not, that de facto that one is somehow not configured as intended.<\/p>\n

    Common causes \/ things to check<\/h2>\n

    1. Contention: waht’s the CPU + C libraries doing in background? If system has any significant (but small) load, you could be contended on I\/O, CPU mgiht not be interrupting to shunt data from hardware up to software (kernel), up to software (OS user), up to JVM<\/p>\n

    Classic example: MySQL DB running on a system can block I\/O even with small CPU load<\/p>\n

    2. file-level locking in OS FS. Check using lsof<\/a> which files your JVM is accessing, and what other processes in the machine may have same files open.<\/p>\n

    (NB: there’s a bunch of tools like “lsof” which let you see which files are in use by which processes in a unix\/linux system. As a network programmer, you should learn them all – they can save a lot of time in development. As a network programmer, you need to be a competent SysAdmin!)<\/p>\n

    Classic problem: something unexpected has an outstanding read (or a pre-emptive write lock) which is causing silliness. I remember several times having a text editor open, or etc, that was inadvertently slowing access to local files (doh).<\/p>\n

    3. can you snoop the traffic? (i.e. its socket, not pipe)<\/p>\n

    Classic problem: some unrelated service is bombarding the loopback with crap. eg. Windows networking (samba on linux) going nuts<\/p>\n

    Try running Wireshark, filtered to show only 127. and see what’s going through at same time<\/p>\n

    Also: this is a good way to check where the delay is happening. Is it at point of send, or point of receive? … both?<\/p>\n

    There’s “net traffic” and there’s “net traffic”. Wireshark often shows traffic that OS normally filters out from monitoring apps…<\/p>\n

    4. Check your routing table? AND: Check it’s not changing before \/ aftter the attempted read?<\/p>\n

    5. Try enabling Nagle<\/a>, see if it has any effect?<\/p>\n

    My point is: use this as a check: it ought to make things worse. If not … perhaps the disabling wasn’t working?<\/p>\n

    6. Have you done ANY traffic shaping (or firewalling) on this machine at any time in the past?<\/p>\n

    Linux: in particular, check the iptables<\/a> output. Might be an old iptables rule still stuck in there – or even a firewall rule.<\/p>\n

    Linux + Windows: disable all firewalls, completely.<\/p>\n

    7. Similarly: do you have any Anti-Virus software?<\/p>\n

    Disconnect your test machines from the internet, and remove all AV.<\/p>\n

    AV software can even corrupt your files when they mistakenly think that the binary files used by the compiler\/linker are “suspicious” (IIRC, that happened to us with early PlayStation3 devkits).<\/p>\n

    8. On a related note: security \/ IPS tools installed? They will often insert artificial delays silently.<\/p>\n

    CHECK YOUR SYSTEM LOG FILES! …whatever is causing the delay is quite possibly reporting at least a “warning” of some kind.<\/p>\n

    9. (in this case, Cas’s socket is using SSL): Perhaps something is looking up a certificate remotely over the web?<\/p>\n

    …checked your certificate chain? (if there’s an unknown \/ suspicious cert in the chain, your OS might be trying to check \/ resolve it before it allows the connection)<\/p>\n

    10. (in this case, Cas is using custom SSL code in Java to “hack” it): Get a real SSL cert from somewhere, see if it behaves any different<\/p>\n

    (I think it would be very reasonable for your OS to detect any odd SSL stuff and delay it, as part of anti-malware \/ virus protection!)<\/p>\n

    11. “Is it cos I is custom?” – Setup an off-the-shelf webserver on the same machine and check if YOUR READING CODE can read from that SSL localhost fast?<\/p>\n

    (it often helps to get an answer to “is it the writer, the reader, both … is it the hacked SSL, or all SSL?” etc)<\/p>\n

    12. (getting specific now, as the general ideas didn’t help): if you bind to the local IP address instead of 127 ?<\/p>\n

    13. Howabout reverse-DNS? (again, 4 seconds is in the realm of a failed DNS lookup)<\/p>\n

    Might be a reverse DNS issue … e.g. something in OS (kernel or virus protection), or in JVM SSL library, that’s trying to reverse-lookup the 127 address in order to resolve some aspect of SSL.<\/p>\n

    I’ve had to put fake entries into hosts file in the past to speed-up this stuff, some libs just need a quick answer<\/p>\n

    Result<\/h2>\n

    Turns out we were able to stop here…<\/p>\n

    \nCas: “Well, whaddya know. It was a hosts lookup after all – because I’m using 127.0.0.2 and 127.0.0.3 it was doing a hostname lookup. I added those to hosts and all is solved\n<\/p><\/blockquote>\n

    \nMe: “(dance)” (yeah. It was skype. The dance smiley comes in handy)\n<\/p><\/blockquote>\n","protected":false},"excerpt":{"rendered":"

    Cas (@PuppyGames) (of PuppyGames fame – Titan Attacks, Revenge of the Titans, etc) is working on an awesome new MMO RTS … thing. He had a weird networking problem, and was looking for suggestions on possible causes. I used to do a lot of MMO dev, so we ran through the “typical” problems. This isn’t […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[34,20],"tags":[],"_links":{"self":[{"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/posts\/3216"}],"collection":[{"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/comments?post=3216"}],"version-history":[{"count":3,"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/posts\/3216\/revisions"}],"predecessor-version":[{"id":3219,"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/posts\/3216\/revisions\/3219"}],"wp:attachment":[{"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/media?parent=3216"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/categories?post=3216"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/new.t-machine.org\/index.php\/wp-json\/wp\/v2\/tags?post=3216"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}