O(n) logging?



  • Recently, I was trying to log in to the VPN of a customer to get some work done. So I started the VPN client, got the login screen, entered my password and what happened next was kind of weird. I got the usual splash screen while the client tries to connect, I get a "green light" icon in the taskbar status area for a completed connection, but only for a fraction of a second, then the VPN disconnects and the login dialog reappears. No error message, no nothing. WTF?

    I'll spare you the details of half a day of desperately trying to get the connection to work, the fruitless phone calls to the customer's IT help desk to see whether there was a problem on their side (there wasn't) and all that stuff and jump right to the conclusion.

    So, while trying to figure out what was wrong I was trawling through the log files of the VPN client to see if there was anything in there giving me a clue, but there weren't any "smoking gun" failure messages either - according to the log, the connection simply was successful, but then immediately terminated again for no reason. Eventually, I had the idea to look at the log file 'live' while a login attempt was ongoing, and that was when I noticed that a) the log messages were coming in extremely slowly (like, 0.5-1 seconds between each, even clearly related messages) and b) the new login dialog was already popping up even while the previous login attempt was still logging its output to the file!

    Even though I was thinking "Oh, please, it can't really be that, noone would be that stupid", on a hunch I simply attempted to delete the log file (which was only about 6 MB in size at the time - somewhat large, but not really big for a log file), and tried to log in again - and guess what: the next attempt to log in worked. A quick look into the new log file confirmed that the messages were now written in rapid succession instead of the leisurly pace of before.

    My conclusion (which, while it seems obvious, I still can't wrap my head around) is that the method the VPN client uses to append messages to the log file somehow has a run time dependent on the current size of the log file (what is it doing? is it reading the entire file first, before adding the message in-memory and then writing the contents back or what?!), and after an extended period of using the client regularly, the log file had finally grown large enough that the accumulated delay of writing the entire log output for the login process caused the client to run into some kind of timeout condition, apparently making it assume the connection had failed when it had actually succeeded.

    After picking my head up from the desk, I could finally get to work; but I still wonder how that kind of code managed to make its way into a professional, commercial, enterprise-"quality" piece of software...



  • Well don't leave us in suspense . . . who produced this piece of software? Is it a homonym of Sysco?



  • Now, all we need you to do is add a bit of extra stuff involving Hanzo, the president's daughter or an imcompetent manager. Then we have a front page article.

    BTW: Great detective work 🙂

     



  • When I write code to write to log files, I always use the append file write method. However, specifically try to avoid the problem you're seeing by having the log filename based on the date. This means you only get a day's worth of logging at most before it starts logging to a new file. It's also easier to find events when they are grouped into dated files.

    Out of curiosity I wrote a quick console app in .NET to try appending to the file (using System.IO.File.AppendAllText) - it was writing very quickly even when the file was over 100MB in size - less than a hundredth of a second.

    I then re-wrote to get it to read the entire contents, append the new line and write back. By the time the file reached about 2MB it was taking 2 seconds to write a row. So that would appear to be what they are doing - a definite WTF.



  • @ochrist said:

    Now, all we need you to do is add a bit of extra stuff involving Hanzo, the president's daughter or an imcompetent manager. Then we have a front page article.

    BTW: Great detective work 🙂

     

    And change the title to "Log(n)"


  • @FragFrog said:

    And change the title to "Log(n)"
    I was trying to think of a pun based on O(log(n)) or something but somehow I was too tired to really to come up with anything good...



  • @Quango said:

    When I write code to write to log files, I always use the append file write method. However, specifically try to avoid the problem you're seeing by having the log filename based on the date. This means you only get a day's worth of logging at most before it starts logging to a new file. It's also easier to find events when they are grouped into dated files.

    Out of curiosity I wrote a quick console app in .NET to try appending to the file (using System.IO.File.AppendAllText) - it was writing very quickly even when the file was over 100MB in size - less than a hundredth of a second.

    I then re-wrote to get it to read the entire contents, append the new line and write back. By the time the file reached about 2MB it was taking 2 seconds to write a row. So that would appear to be what they are doing - a definite WTF.

     

     

    or their skip-to-end is reading until EOF and then writing the line because they never heard of the "a" option in fopen and instead use "w+"








  • It was a cold day in Bellarus, where Comrade Czernobog was working the night shift. It had been a long week of working with a new client, a massive banking corporation with interests across the globe. Their internal cloud driven spreadsheet management system was acting up again, and Czernobog's company's SLA required the problem be resolved within 12 hours. He had already spent 4 of those hours tracking down the correct server, but he was confident he was reaching the home stretch. He booted up his VPN client and entered the login details for the server, went to take a 5 minute break while it connected, and had a coffee on the balcony overlooking the abattoir, remembering the good old days.



    When he returned to his desk, he found nothing but the login screen waiting for him. Surprised, he assumed he must have been away for too long and the session must have timed out. He re-entered his login details, got the familiar splash screen, and a green light indicating successful connection, before being unceremoniously bumped back to the login screen again. Czernobog was not a particularly patient man, and his frustration was already starting to get to him, he could feel the anger rising in him, particularly as there was now only 7 hours left to fix the problem. He couldn't afford to be wasting time with a broken VPN connection.



    After spending 20 minutes on hold with the client's IT department, he finally got through to a human. He explained the problem he was experiencing and that he expected the entire server may well need restarting. The IT department made it clear that there was nothing wrong at their end, all cylinders firing normally. They suggested he check with his company's ISP, to ensure connections outside of the soviet motherland were not being blocked by the iron firecurtain. Frustrated that these capitalist pigs would make such allegations against his glorious nation, Czernobog's blood began to run hotter. Clearly the client's IT department were not going to be any further help.



    Czernobog spent the next 4 hours testing every kind of connection to the target he could think of. He Pinged the server, traced the routes, connected to other services, anything he could think of. Everything worked fine, the only thing failing was the VPN connection. His frustration led him to desperation, restarting just about every piece of equipment between him and the client that he had the ability to restart. Nothing helped. With just over 3 hours left to go, his SLA time limit was starting to loom large. He no longer had the luxury of time on his side.



    Czernobog decided to delve into the logs of the VPN client and see if anything popped out as obviously wrong. Nothing. Just a long list of successful connections and disconnections. Nothing obviously wrong. Useless capitalist logging, keeping the valuable information away from the populace and in the hands of the fat cats. Czernobog was getting tired of it. He decided to keep an eye on the logs whilst he connected to the server and see what happened. The log was being written with his connection, but very slowly, taking a couple of seconds to write his connection attempt into the logs. He immediately realised what was the problem, he was not stupid. Those wretched capitalist pigs were being sent all the pertinent information about his login attempt, and after the fat cats had their fill, he got the crumbs of information left over, the only stuff they deigned him worthy of receiving. His blood, red as his communist ideals, boiled.



    With just a couple of hours left over, and his frustration reaching boiling point. Czernobog decided he would not work with the crumbs these capitalists allowed him. His frustration was too much, and he deleted the log file in a rage. "Hah! I will have nothing rather than your leavings, capitalist dogs!" he cried at his screen. This was too much, he needed to take another break. As he went to get another coffee, he stroked the handle of his sledge hammer affectionately as he went by. By now it was approaching dawn, and the abattoir was gearing up for the day, he could hear the animals in the holding pens.



    Returning to his desk, he had just half an hour left to work with on his SLA. His comrades at the company were coming in to start their morning shifts, and he should already have clocked out, but he couldn't let them win. He booted up the VPN client one more time and attempted a connection, this time everything worked like a dream, and the log file was written instantly. Czernobog was taken aback, he realised the capitalists must have tapped into his computer's microphone, heard his angry statements and realised he was onto them, and quickly removed all traces of their presence. Happy in his confidence that he had saved the motherland from this despicable spy network, he logged onto the server and identified the problem, a windows service in an error state. He restarted the service and everything was fine once more. His work here was done.



    Satisfied with an evening's work well done, Czernobog closed down his machine, and clocked out. His boss was just clocking in when he got there, and Czernobog filled him in on the evening's events, and counselled him to be careful of this client, as they may well be involved with capitalist spying. He turned to leave, picking up his sledgehammer as he did so. "I am going to relive the good old days today" he said to his boss, as a farewell "I will clock in after I have cleaned up".



    Czernobog stepped out of the office just as the sun was rising, he hoisted the sledgehammer onto his shoulder, and strode purposefully to his next destination.



  • @Algorythmics said:

    It was a cold day in Bellarus, where Comrade Czernobog was...

    Brilliant. Add a few misspellings and it could be brillant.



  • @boomzilla said:

    @Algorythmics said:
    It was a cold day in Bellarus, where Comrade Czernobog was...

    Brilliant. Add a few misspellings and it could be brillant.

    Not enough Java.



  •  We also need Czernobog to change to Cynthia somewhere in the text.



  • @Algorythmics said:

    It was a cold day in Bellarus, where Comrade Czernobog was working the night shift...

    You even managed to excise the actual WTF, this is front-page material.



  • @Anonymouse said:

    on a hunch I simply attempted to delete the log file (which was only about 6 MB in size at the time - somewhat large, but not really big for a log file)

    according to this article, 1030 Mbps is normal for a hard drive. Which Google says would take about 0.043 seconds.

    Since you said the file took 0.5 to 1 second to show each log message when it was 6MB, and nearly 0 seconds to show each log message when it started empty, let's do some science. It could be O(n), but since you hadn't noticed it before, it could be something more like O(n2) or O(2n), or even O(n!n-k) if they used bogobogosort to sort the log file.



  • @Ben L. said:

    Since you said the file took 0.5 to 1 second to show each log message when it was 6MB, and nearly 0 seconds to show each log message when it started empty, let's do some science. It could be O(n), but since you hadn't noticed it before, it could be something more like O(n2) or O(2n), or even O(n!n-k) if they used bogobogosort to sort the log file.

    I'm still waiting on a Quantum bogosort implementation, which will truly break the theoretical lower bound of O(n log(n)) for sorting algorithms because it is O(n)

    Given: a list to be sorted
    1. Shuffle the list
    2. If the list is not sorted, destroy the universe


  • @dtech said:

    @Ben L. said:
    Since you said the file took 0.5 to 1 second to show each log message when it was 6MB, and nearly 0 seconds to show each log message when it started empty, let's do some science. It could be O(n), but since you hadn't noticed it before, it could be something more like O(n2) or O(2n), or even O(n!n-k) if they used bogobogosort to sort the log file.

    I'm still waiting on a Quantum bogosort implementation, which will truly break the theoretical lower bound of O(n log(n)) for sorting algorithms because it is O(n)

    Given: a list to be sorted
    1. Shuffle the list
    2. If the list is not sorted, destroy the universe
    In order for quantum bogosort to be efficient, it needs to spawn n! copies of the current universe. Therefore, it is O(n!k), where n is the length of the array and k is the number of particles in the universe when the sorting begins.


  • @Algorythmics said:


    It was a cold day in Bellarus, where Comrade Czernobog was working the night shift.




    BRILLANT! That was a better read than most front page articles!


  • Discourse touched me in a no-no place

    @dtech said:

    I'm still waiting on a Quantum bogosort implementation, which will truly break the theoretical lower bound of O(n log(n)) for sorting algorithms because it is O(n)
    But pigeonhole sort is already O(n). We don't need that high-falutin' quantum malarkey.


  • Discourse touched me in a no-no place

    @boomzilla said:

    @Algorythmics said:
    It was a cold day in Bellarus, where Comrade Czernobog was...

    Brilliant. Add a few misspellings and it could be brillant.

    Belarus is misspelled. Does that count?



  • @Ben L. said:

    In order for quantum bogosort to be efficient, it needs to spawn n! copies of the current universe. Therefore, it is O(n!k), where n is the length of the array and k is the number of particles in the universe when the sorting begins.

    But k is a constant so it can be ignored in the big-O expression.

    A quick search shows that the number of baryons (stable particles) in the universe is 1E80 and 59! is larger than this. Factorials get really big astonishingly fast.
    (Actually I was trying to make a joke when I said that k could be ignored but I proved myself unfunny.)



  • @Ben L. said:

    @Anonymouse said:
    on a hunch I simply attempted to delete the log file (which was only about 6 MB in size at the time - somewhat large, but not really big for a log file)

    according to this article, 1030 Mbps is normal for a hard drive. Which Google says would take about 0.043 seconds.

    Since you said the file took 0.5 to 1 second to show each log message when it was 6MB, and nearly 0 seconds to show each log message when it started empty, let's do some science. It could be O(n), but since you hadn't noticed it before, it could be something more like O(n2) or O(2n), or even O(n!n-k) if they used bogobogosort to sort the log file.

    Sequential data rates don't mean much for spinning disk hard drives, the seek time is far more important. Seek times, iirc, average about 10-15ms for most mechanical drives. Worst case, you getline(), then do a blocking wait for it, and getline() again. 10ms/line quickly becomes an insane amount of time.


  • Discourse touched me in a no-no place

    @Buttembly Coder said:

    Sequential data rates don't mean much for spinning disk hard drives, the seek time is far more important. Seek times, iirc, average about 10-15ms for most mechanical drives. Worst case, you getline(), then do a blocking wait for it, and getline() again. 10ms/line quickly becomes an insane amount of time.
    Fortunately, that's not all that's going on. The OS really reads more than a line at a time and buffers things for you, meaning that the per-line seek time is rather less than the time to wait for the disk to spin round. You only really notice that time when you sync() and that's the main cost with a DB transaction commit, which is why DBs benefit so much from SSDs.

    Or you could just speed things up by using MySQL with MyISAM. After all, data integrity isn't nearly so important as speed…



  • @Buttembly Coder said:

    @Ben L. said:
    @Anonymouse said:
    on a hunch I simply attempted to delete the log file (which was only about 6 MB in size at the time - somewhat large, but not really big for a log file)

    according to this article, 1030 Mbps is normal for a hard drive. Which Google says would take about 0.043 seconds.

    Since you said the file took 0.5 to 1 second to show each log message when it was 6MB, and nearly 0 seconds to show each log message when it started empty, let's do some science. It could be O(n), but since you hadn't noticed it before, it could be something more like O(n2) or O(2n), or even O(n!n-k) if they used bogobogosort to sort the log file.

    Sequential data rates don't mean much for spinning disk hard drives, the seek time is far more important. Seek times, iirc, average about 10-15ms for most mechanical drives. Worst case, you getline(), then do a blocking wait for it, and getline() again. 10ms/line quickly becomes an insane amount of time.

     

    exactly. Hard drives are very slow. Random reads and writes are for normal hdds below 1MB/s.That why SSDs are brillant with their 50MB/s++ random read speeds. Not because of their sequential speeds.

    And then there is this:

    The Java RandomAccessFile class even in Java 7 (maybe also 😎 has a readLine() method that reads the file byte by byte until it find, guess what, (\r)\n. Therefore this method is pretty much unusable and very slow. So any application using it will have terrible perfromance.

     

     

     


Log in to reply
 

Looks like your connection to What the Daily WTF? was lost, please wait while we try to reconnect.