2013-04-22 23:39:37

by Felix Becker

[permalink] [raw]
Subject: socket file descriptor a/m/c-timestamps broken in <= 3.8.8?

Hi,

I tried to figure out how old my TCP connections are and took a look
at /proc/<pid>/fd/<socketfdnum> using 'ls -la' / 'stat'.

When I'm creating a new socket in my application, the time stamps
returned by stat / ls -la are correct - as expected. After closing the
socket, the fd isn't visible in /proc/<pid>/fd anymore - as expected.
When creating a new socket a few minutes later (which gets the same
number as the socket closed before), the newly created socket has the
same time stamps (access / modify / change) as the old socket - I
didn't expect this.

When using fstat() from <sys/stat.h> I'm getting 0 for a/m/c-time.
Only in /proc/<pid>/fd/ i can see (the wrong) times.

I attached a test code for reproducing the issue. In my production
environments i have new socket file descriptors which have timestamps
indicating that they are many hours old.

Q1: is it a bug that fstat() returns 0-values for a/m/c-time?

Q2: is it a bug that a new socket, with the file descriptor number of
an older socket which existed before, have the a/m/c-times of the old
socket in /proc/<pid>/fd/?

Best regards

Felix

p.s. test setup is a normal x86_64 architecture (intel xeon).

=======================================================================
// sockettest.c

#include <sys/socket.h>
#include <time.h>
#include <sys/stat.h>
#include <sys/types.h>
#include <sys/un.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <unistd.h>


void print_socket_stats(int sfd){
struct stat socket_stats;
fstat(sfd, &socket_stats);
printf("Socket stats for socket %d\n", sfd);
printf("socket stat: st_atime: %ld\n", socket_stats.st_atime);
printf("socket stat: st_mtime: %ld\n", socket_stats.st_mtime);
printf("socket stat: st_ctime: %ld\n", socket_stats.st_ctime);
}

void print_with_time(const char* message){
time_t t;
time(&t);
printf("%s @ %s\n", message, ctime(&t));

}

int main(int argc, char *argv[]) {

int sfd;

printf("pid: %d\n", getpid());

print_with_time("Opening socket");
sfd = socket(AF_UNIX, SOCK_STREAM, 0);
printf("opened socket: %d\n",sfd);
print_socket_stats(sfd);

print_with_time("sleeping 30\n");

sleep(30);

printf("closing socket %d", sfd);
close(sfd);

printf("closed socket: %d\n",sfd);
print_with_time("sleeping 61 seconds");

sleep(61);

print_with_time("opening new socket");
sfd = socket(AF_UNIX, SOCK_STREAM, 0);
printf("opened socket: %d\n",sfd);
print_socket_stats(sfd);
print_with_time("sleeping 999");

sleep(999);
}

=======================================================================

./sockettest &

pid: 18267
Opening socket @ Mon Apr 22 23:05:37 2013

opened socket: 3
Socket stats for socket 3
socket stat: st_atime: 0
socket stat: st_mtime: 0
socket stat: st_ctime: 0
sleeping 30 @ Mon Apr 22 23:05:37 2013

>>> ls -la /proc/18267/fd/3
lrwx------ 1 becker becker 64 Apr 22 23:05 /proc/18267/fd/3 ->
socket:[210268]


>>> stat /proc/18267/fd/3
File: `/proc/18267/fd/3' -> `socket:[210268]'
Size: 64 Blocks: 0 IO Block: 1024 symbolic link
Device: 3h/3d Inode: 52177 Links: 1
Access: (0700/lrwx------) Uid: ( 1001/ becker) Gid: ( 1001/ becker)
Access: 2013-04-22 23:05:46.179813835 +0000
Modify: 2013-04-22 23:05:46.175813886 +0000
Change: 2013-04-22 23:05:46.175813886 +0000

closing socket 3
closed socket: 3

sleeping 61 seconds @ Mon Apr 22 23:06:07 2013

opening new socket @ Mon Apr 22 23:07:08 2013

opened socket: 3
Socket stats for socket 3
socket stat: st_atime: 0
socket stat: st_mtime: 0
socket stat: st_ctime: 0
sleeping 999 @ Mon Apr 22 23:07:08 2013


>>> ls -la /proc/18267/fd/3
lrwx------ 1 becker becker 64 Apr 22 23:05 /proc/18267/fd/3 ->
socket:[210320]

>>> stat /proc/18267/fd/3



File: `/proc/18267/fd/3' -> `socket:[210320]'
Size: 64 Blocks: 0 IO Block: 1024 symbolic link
Device: 3h/3d Inode: 52177 Links: 1
Access: (0700/lrwx------) Uid: ( 1001/ becker) Gid: ( 1001/ becker)
Access: 2013-04-22 23:05:46.179813835 +0000
Modify: 2013-04-22 23:05:46.175813886 +0000
Change: 2013-04-22 23:05:46.175813886 +0000


2013-04-23 00:30:18

by Eric Wong

[permalink] [raw]
Subject: Re: socket file descriptor a/m/c-timestamps broken in <= 3.8.8?

Cc:-ing netdev (no comments of my own)

Felix Becker <[email protected]> wrote:
> Hi,
>
> I tried to figure out how old my TCP connections are and took a look
> at /proc/<pid>/fd/<socketfdnum> using 'ls -la' / 'stat'.
>
> When I'm creating a new socket in my application, the time stamps
> returned by stat / ls -la are correct - as expected. After closing the
> socket, the fd isn't visible in /proc/<pid>/fd anymore - as expected.
> When creating a new socket a few minutes later (which gets the same
> number as the socket closed before), the newly created socket has the
> same time stamps (access / modify / change) as the old socket - I
> didn't expect this.
>
> When using fstat() from <sys/stat.h> I'm getting 0 for a/m/c-time.
> Only in /proc/<pid>/fd/ i can see (the wrong) times.
>
> I attached a test code for reproducing the issue. In my production
> environments i have new socket file descriptors which have timestamps
> indicating that they are many hours old.
>
> Q1: is it a bug that fstat() returns 0-values for a/m/c-time?
>
> Q2: is it a bug that a new socket, with the file descriptor number of
> an older socket which existed before, have the a/m/c-times of the old
> socket in /proc/<pid>/fd/?
>
> Best regards
>
> Felix
>
> p.s. test setup is a normal x86_64 architecture (intel xeon).
>
> =======================================================================
> // sockettest.c
>
> #include <sys/socket.h>
> #include <time.h>
> #include <sys/stat.h>
> #include <sys/types.h>
> #include <sys/un.h>
> #include <stdlib.h>
> #include <stdio.h>
> #include <string.h>
> #include <unistd.h>
>
>
> void print_socket_stats(int sfd){
> struct stat socket_stats;
> fstat(sfd, &socket_stats);
> printf("Socket stats for socket %d\n", sfd);
> printf("socket stat: st_atime: %ld\n", socket_stats.st_atime);
> printf("socket stat: st_mtime: %ld\n", socket_stats.st_mtime);
> printf("socket stat: st_ctime: %ld\n", socket_stats.st_ctime);
> }
>
> void print_with_time(const char* message){
> time_t t;
> time(&t);
> printf("%s @ %s\n", message, ctime(&t));
>
> }
>
> int main(int argc, char *argv[]) {
>
> int sfd;
>
> printf("pid: %d\n", getpid());
>
> print_with_time("Opening socket");
> sfd = socket(AF_UNIX, SOCK_STREAM, 0);
> printf("opened socket: %d\n",sfd);
> print_socket_stats(sfd);
>
> print_with_time("sleeping 30\n");
>
> sleep(30);
>
> printf("closing socket %d", sfd);
> close(sfd);
>
> printf("closed socket: %d\n",sfd);
> print_with_time("sleeping 61 seconds");
>
> sleep(61);
>
> print_with_time("opening new socket");
> sfd = socket(AF_UNIX, SOCK_STREAM, 0);
> printf("opened socket: %d\n",sfd);
> print_socket_stats(sfd);
> print_with_time("sleeping 999");
>
> sleep(999);
> }
>
> =======================================================================
>
> ./sockettest &
>
> pid: 18267
> Opening socket @ Mon Apr 22 23:05:37 2013
>
> opened socket: 3
> Socket stats for socket 3
> socket stat: st_atime: 0
> socket stat: st_mtime: 0
> socket stat: st_ctime: 0
> sleeping 30 @ Mon Apr 22 23:05:37 2013
>
> >>> ls -la /proc/18267/fd/3
> lrwx------ 1 becker becker 64 Apr 22 23:05 /proc/18267/fd/3 ->
> socket:[210268]
>
>
> >>> stat /proc/18267/fd/3
> File: `/proc/18267/fd/3' -> `socket:[210268]'
> Size: 64 Blocks: 0 IO Block: 1024 symbolic link
> Device: 3h/3d Inode: 52177 Links: 1
> Access: (0700/lrwx------) Uid: ( 1001/ becker) Gid: ( 1001/ becker)
> Access: 2013-04-22 23:05:46.179813835 +0000
> Modify: 2013-04-22 23:05:46.175813886 +0000
> Change: 2013-04-22 23:05:46.175813886 +0000
>
> closing socket 3
> closed socket: 3
>
> sleeping 61 seconds @ Mon Apr 22 23:06:07 2013
>
> opening new socket @ Mon Apr 22 23:07:08 2013
>
> opened socket: 3
> Socket stats for socket 3
> socket stat: st_atime: 0
> socket stat: st_mtime: 0
> socket stat: st_ctime: 0
> sleeping 999 @ Mon Apr 22 23:07:08 2013
>
>
> >>> ls -la /proc/18267/fd/3
> lrwx------ 1 becker becker 64 Apr 22 23:05 /proc/18267/fd/3 ->
> socket:[210320]
>
> >>> stat /proc/18267/fd/3
>
>
>
> File: `/proc/18267/fd/3' -> `socket:[210320]'
> Size: 64 Blocks: 0 IO Block: 1024 symbolic link
> Device: 3h/3d Inode: 52177 Links: 1
> Access: (0700/lrwx------) Uid: ( 1001/ becker) Gid: ( 1001/ becker)
> Access: 2013-04-22 23:05:46.179813835 +0000
> Modify: 2013-04-22 23:05:46.175813886 +0000
> Change: 2013-04-22 23:05:46.175813886 +0000
> --

2013-04-23 00:37:40

by Eric Dumazet

[permalink] [raw]
Subject: Re: socket file descriptor a/m/c-timestamps broken in <= 3.8.8?

On Tue, 2013-04-23 at 00:30 +0000, Eric Wong wrote:
> Cc:-ing netdev (no comments of my own)
>
> Felix Becker <[email protected]> wrote:
> > Hi,
> >
> > I tried to figure out how old my TCP connections are and took a look
> > at /proc/<pid>/fd/<socketfdnum> using 'ls -la' / 'stat'.
> >

Thanks, but its not a network issue, /proc/pid/fd are part of another
subsystem.

In particular, a/m/c timestamps are volatile (not meaningfull), as you
can make them disappear by
"echo 3 >/proc/sys/vm/drop_caches"

Next time you use "ls /proc/pid/fd/..." timestamps are created.


2013-04-23 22:53:05

by Felix Becker

[permalink] [raw]
Subject: Re: socket file descriptor a/m/c-timestamps broken in <= 3.8.8?

Hi,

thank you for that info. Can you tell which mailing list the right one
for this issue is?

Felix

On 04/23/2013 02:37 AM, Eric Dumazet wrote:
> On Tue, 2013-04-23 at 00:30 +0000, Eric Wong wrote:
>> Cc:-ing netdev (no comments of my own)
>>
>> Felix Becker <[email protected]> wrote:
>>> Hi,
>>>
>>> I tried to figure out how old my TCP connections are and took
>>> a look at /proc/<pid>/fd/<socketfdnum> using 'ls -la' /
>>> 'stat'.
>>>
>
> Thanks, but its not a network issue, /proc/pid/fd are part of
> another subsystem.
>
> In particular, a/m/c timestamps are volatile (not meaningfull), as
> you can make them disappear by "echo 3 >/proc/sys/vm/drop_caches"
>
> Next time you use "ls /proc/pid/fd/..." timestamps are created.
>
>
>
> -- To unsubscribe from this list: send the line "unsubscribe
> linux-kernel" in the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>

2013-04-23 23:18:10

by Eric Dumazet

[permalink] [raw]
Subject: Re: socket file descriptor a/m/c-timestamps broken in <= 3.8.8?

On Wed, 2013-04-24 at 00:53 +0200, Felix Becker wrote:
> Hi,
>
> thank you for that info. Can you tell which mailing list the right one
> for this issue is?

lkml was fine.

I guess you could try to CC Al Viro <[email protected]>