• PHP Help PHP Coding
  • file_exists() on sshfs-mounted filesystem takes 4+ seconds when file does not exist

Hello,

I'm observing a strange problem.

I have a remote filesystem mounted using sshfs (in Debian Linux); this mount-point is established at boot-time via fstab.

When I call PHP's file_exists() function to determine whether or not a particular file exists on the sshfs-mounted filesystem, the function takes over 4 seconds to complete when the file does not exist, but at the same time, the function completes in 0.001 seconds when the file does exist.

Why would PHP take so much longer to determine that the file does not exist? I have read elsewhere that file_exists() performance is largely contingent upon the underlying OS's stat() function. So, I tried stat-ing the files via the terminal and the results come back instantly (e.g., one thousandth of a second), whether the file exists or not.

Does anyone have any idea what might be happening here? I have tried this on two different systems and the problem only happens on one of the systems.

The connection speed between the two servers seems irrelevant given that the file_exists() call happens so quickly when the file does exist.

I really appreciate any help with this.

    Well, I'll bite, but I'm sure I'm of no help at all. 🙁

    Since the FS is mounted, there's no authentication to do, am I correct?

    PHP does cache results of file_exists() calls for existing files, though (see [man]clearstatcache[/man]), so that might explain why it's faster for extant files?

      Hi, thanks for jumping-in! Every clue is a potential solution!

      That's correct; the filesystem is mounted. I assume that the authentication is performed once upon mounting and perhaps periodically thereafter (but not on every filesystem request). The mounting happens via fstab using a "sshfs" entry that leverages public key authentication.

      I should have mentioned that I did try calling clearstatcache() just before making each call to file_exists(). Surprisingly, this doubles the execution time for file_exists() when the file does not exist, but doesn't affect the time required when the file does exist.

      Without the calls to clearstatcache() - files do not exist:

      Checking for file "/ndtcat/dev/back-1/mp3/2885.mp3...
      Check required 4.377338886261 seconds
      Checking for file "/ndtcat/dev/back-1/flac/2885.flac...
      Check required 4.3129899501801 seconds
      Checking for file "/ndtcat/dev/back-1/mp3/2886.mp3...
      Check required 4.2456741333008 seconds
      Checking for file "/ndtcat/dev/back-1/flac/2886.flac...
      Check required 4.2454588413239 seconds
      Checking for file "/ndtcat/dev/back-1/mp3/2887.mp3...
      Check required 4.3836197853088 seconds
      Checking for file "/ndtcat/dev/back-1/flac/2887.flac...
      Check required 4.2531359195709 seconds
      

      With the calls to clearstatcache() - files do not exist:

      Checking for file "/ndtcat/dev/back-1/mp3/2885.mp3...
      Check required 8.5778198242188 seconds
      Checking for file "/ndtcat/dev/back-1/flac/2885.flac...
      Check required 8.5042169094086 seconds
      Checking for file "/ndtcat/dev/back-1/mp3/2886.mp3...
      Check required 8.5915818214417 seconds
      Checking for file "/ndtcat/dev/back-1/flac/2886.flac...
      Check required 8.4928848743439 seconds
      Checking for file "/ndtcat/dev/back-1/mp3/2887.mp3...
      Check required 8.4456911087036 seconds
      Checking for file "/ndtcat/dev/back-1/flac/2887.flac...
      Check required 8.5748710632324 seconds
      

      Without the calls to clearstatcache() - files do exist:

      
      Checking for file "/ndtcat/dev/back-1/mp3/6094.mp3...
      Check required 0.0017569065093994 seconds
      Checking for file "/ndtcat/dev/back-1/flac/6094.flac...
      Check required 0.0017290115356445 seconds
      Checking for file "/ndtcat/dev/back-1/mp3/6095.mp3...
      Check required 0.00187087059021 seconds
      Checking for file "/ndtcat/dev/back-1/flac/6095.flac...
      Check required 0.0017759799957275 seconds
      Checking for file "/ndtcat/dev/back-1/mp3/6096.mp3...
      Check required 0.0018107891082764 seconds
      Checking for file "/ndtcat/dev/back-1/flac/6096.flac...
      Check required 0.0018069744110107 seconds
      

      With the calls to clearstatcache() - files do exist:

      Checking for file "/ndtcat/dev/back-1/mp3/6094.mp3...
      Check required 0.0018830299377441 seconds
      Checking for file "/ndtcat/dev/back-1/flac/6094.flac...
      Check required 0.001823902130127 seconds
      Checking for file "/ndtcat/dev/back-1/mp3/6095.mp3...
      Check required 0.0018379688262939 seconds
      Checking for file "/ndtcat/dev/back-1/flac/6095.flac...
      Check required 0.0018370151519775 seconds
      Checking for file "/ndtcat/dev/back-1/mp3/6096.mp3...
      Check required 0.0017740726470947 seconds
      Checking for file "/ndtcat/dev/back-1/flac/6096.flac...
      Check required 0.0017499923706055 seconds
      

      Any thought as to why calling clearstatcache() makes each check take twice as long for non-existent files?

      What I find strange is that I can scandir() the directory in which I am checking for the file, and the results come back immediately. There are hundreds of files in this directory. Is it just me, or does it make zero sense to be able to list the entire directory contents in a fraction of a second, but require 4+ seconds to check for the existence of a single file within it?

      Also, as mentioned in my OP, the operating system is able to determine more or less instantly that the file doesn't exist (tested by calling "stat /path/to/file" on the terminal). Why does PHP take so much longer, especially if it is leveraging the OS's stat function?

      When I execute my test script, and then check jnettop, I can see "light network activity" -- exactly 4.75KB/s -- between the local server and the remote server that contains the files for whose existence I am checking. I find it strange that when I run my test script this connection always ramps-up to 4.75KB/s within a few seconds and remains at 4.75KB/s for the duration of the calls to file_exists(). It's strange that a) this connection is "capped" at 4.75KB/s, yet I am able to copy binary data from the same remote server (in the same script) at over 3MB/s; and b) that 4.75KB/s for ~25 seconds would actually be required simply to determine if a file exists.

      Another observation: if I change the call from file_exists() to is_file(), filesize(), etc., the function execution times are the same. 4+ seconds apiece.

      I really hate to have to call "stat" on the command-line to resolve this. Just hate to.

      Any other thoughts?

      Thanks again!

        Just an update.

        I replaced the call to file_exists() with a call to shell_exec('stat "' . $thisFile . '"') and the test script completes almost immediately. This is further proof that the OS is able to determine very quickly that the files don't exist. And, as one would expect, the test takes less time when the file doesn't exist than when it does.

        Checking for file "/ndtcat/dev/back-1/mp3/2885.mp3...
        NULL
        Check required 3.4093856811523E-5 seconds
        Checking for file "/ndtcat/dev/back-1/flac/2885.flac...
        NULL
        Check required 2.2172927856445E-5 seconds
        Checking for file "/ndtcat/dev/back-1/mp3/2886.mp3...
        NULL
        Check required 1.9073486328125E-5 seconds
        Checking for file "/ndtcat/dev/back-1/flac/2886.flac...
        NULL
        Check required 2.0980834960938E-5 seconds
        Checking for file "/ndtcat/dev/back-1/mp3/2887.mp3...
        NULL
        Check required 1.9073486328125E-5 seconds
        Checking for file "/ndtcat/dev/back-1/flac/2887.flac...
        NULL
        Check required 2.0980834960938E-5 seconds
        

        Here are the results of calling "stat" via shell_exec() when the files do exist:

        
        Checking for file "/ndtcat/dev/back-1/mp3/6094.mp3...
        string(369) "  File: `/ndtcat/dev/back-1/mp3/6094.mp3'
          Size: 247541    	Blocks: 488        IO Block: 4096   regular file
        Device: 12h/18d	Inode: 5           Links: 1
        Access: (0644/-rw-r--r--)  Uid: ( 5004/    web1)   Gid: ( 5006/ client1)
        Access: 2013-10-29 12:26:06.000000000 -0400
        Modify: 2013-10-29 12:26:07.000000000 -0400
        Change: 2013-10-29 12:26:07.000000000 -0400
         Birth: -
        "
        Check required 4.6968460083008E-5 seconds
        Checking for file "/ndtcat/dev/back-1/flac/6094.flac...
        string(371) "  File: `/ndtcat/dev/back-1/flac/6094.flac'
          Size: 1500273   	Blocks: 2936       IO Block: 4096   regular file
        Device: 12h/18d	Inode: 4           Links: 1
        Access: (0644/-rw-r--r--)  Uid: ( 5004/    web1)   Gid: ( 5006/ client1)
        Access: 2013-10-29 12:24:18.000000000 -0400
        Modify: 2013-10-29 12:24:19.000000000 -0400
        Change: 2013-10-29 12:24:19.000000000 -0400
         Birth: -
        "
        Check required 2.9087066650391E-5 seconds
        Checking for file "/ndtcat/dev/back-1/mp3/6095.mp3...
        string(369) "  File: `/ndtcat/dev/back-1/mp3/6095.mp3'
          Size: 237506    	Blocks: 464        IO Block: 4096   regular file
        Device: 12h/18d	Inode: 65          Links: 1
        Access: (0644/-rw-r--r--)  Uid: ( 5004/    web1)   Gid: ( 5006/ client1)
        Access: 2013-11-02 13:38:44.000000000 -0400
        Modify: 2013-11-02 13:38:44.000000000 -0400
        Change: 2013-11-02 13:38:44.000000000 -0400
         Birth: -
        "
        Check required 3.0994415283203E-5 seconds
        Checking for file "/ndtcat/dev/back-1/flac/6095.flac...
        string(371) "  File: `/ndtcat/dev/back-1/flac/6095.flac'
          Size: 1201084   	Blocks: 2352       IO Block: 4096   regular file
        Device: 12h/18d	Inode: 63          Links: 1
        Access: (0644/-rw-r--r--)  Uid: ( 5004/    web1)   Gid: ( 5006/ client1)
        Access: 2013-11-02 13:38:40.000000000 -0400
        Modify: 2013-11-02 13:38:41.000000000 -0400
        Change: 2013-11-02 13:38:41.000000000 -0400
         Birth: -
        "
        Check required 2.5033950805664E-5 seconds
        Checking for file "/ndtcat/dev/back-1/mp3/6096.mp3...
        string(369) "  File: `/ndtcat/dev/back-1/mp3/6096.mp3'
          Size: 194367    	Blocks: 384        IO Block: 4096   regular file
        Device: 12h/18d	Inode: 66          Links: 1
        Access: (0644/-rw-r--r--)  Uid: ( 5004/    web1)   Gid: ( 5006/ client1)
        Access: 2013-11-02 13:39:23.000000000 -0400
        Modify: 2013-11-02 13:39:23.000000000 -0400
        Change: 2013-11-02 13:39:23.000000000 -0400
         Birth: -
        "
        Check required 2.6941299438477E-5 seconds
        Checking for file "/ndtcat/dev/back-1/flac/6096.flac...
        string(371) "  File: `/ndtcat/dev/back-1/flac/6096.flac'
          Size: 1061398   	Blocks: 2080       IO Block: 4096   regular file
        Device: 12h/18d	Inode: 64          Links: 1
        Access: (0644/-rw-r--r--)  Uid: ( 5004/    web1)   Gid: ( 5006/ client1)
        Access: 2013-11-02 13:39:20.000000000 -0400
        Modify: 2013-11-02 13:39:20.000000000 -0400
        Change: 2013-11-02 13:39:20.000000000 -0400
         Birth: -
        "
        Check required 1.978874206543E-5 seconds
        

        Again, the tests complete very quickly.

        I wonder how much overhead there is in this "workaround". I don't consider this to be a solution, because it's less cross-platform-friendly.

        What "bugs" me is that this problem doesn't occur on a slightly older, similarly-configured server. What's different? Is this a potential regression in my particular PHP version? Surely someone else would have noticed a problem like this by now.

          At this point I think you're past this forum. It might be a regression in PHP, but proving that will be difficult.

          As for "surely someone else would have noticed" ... I don't know. If it's specific to ssh-mounted remote filesystems, that's not a real common feature (easily doable, I just doubt how many people use it)....

            Write a Reply...