Home / Browse / User-mode Linux kernel port / Mail / Archive

Donate

User-mode Linux kernel port

Email Archive: user-mode-linux-devel (read-only)

Re: [uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly (was Re: g_timeout_add)

From: Jeff Dike <jdike@ad...> - 2008-03-17 17:03

On Fri, Mar 14, 2008 at 11:01:35PM +0000, Nix wrote:
> bash-3.2# ./select-sleep 10
> Slept for 13 seconds.

See what kind of difference the patch below makes - it reduces the 30%
oversleeping down to 10% for me.  That's still way too much, but it's
better.

The problem being fixed here is that setitimer consistently returns a
remaining time greater than what was originally requested, by ~20%:

1205773032.413780 setitimer(ITIMER_VIRTUAL, {it_interval={0, 10000}, it_value={0, 10000}}, NULL) = 0
1205773032.413814 setitimer(ITIMER_VIRTUAL, {it_interval={0, 0},
it_value={0, 0}}, {it_interval={0, 10998}, it_value={0, 11998}}) = 0

This is setting a 100 HZ timer, immediately followed by a cancellation
which also requests the amount left on the timer.  The interval is
rounded up by 10%, and the first tick by 20%.

	       	       	    Jeff

-- 
Work email - jdike at linux dot intel dot com

Index: linux-2.6.22/arch/um/os-Linux/time.c
===================================================================
--- linux-2.6.22.orig/arch/um/os-Linux/time.c	2008-02-18 11:53:51.000000000 -0500
+++ linux-2.6.22/arch/um/os-Linux/time.c	2008-03-17 12:55:41.000000000 -0400
@@ -58,12 +58,17 @@ static inline long long timeval_to_ns(co
 long long disable_timer(void)
 {
 	struct itimerval time = ((struct itimerval) { { 0, 0 }, { 0, 0 } });
+	int remain, max = UM_NSEC_PER_SEC / UM_HZ;
 
 	if (setitimer(ITIMER_VIRTUAL, &time, &time) < 0)
 		printk(UM_KERN_ERR "disable_timer - setitimer failed, "
 		       "errno = %d\n", errno);
 
-	return timeval_to_ns(&time.it_value);
+	remain = timeval_to_ns(&time.it_value);
+	if (remain > max)
+		remain = max;
+
+	return remain;
 }
 
 long long os_nsecs(void)

Thread View

Thread	Author	Date
[uml-devel] g_timeout_add	clowncoder <vincent-perrier@cl...>

Re: [uml-devel] g_timeout_add

From: Jeff Dike <jdike@ad...> - 2008-02-14 00:39

On Wed, Feb 13, 2008 at 08:57:20PM +0100, clowncoder wrote:
> It seems that g_timeout_add glib timeouts are not accurate
> when there is no gtk activity on an uml target.
> 
> This may be a glib problem since I cannot check
> that it does not occur on my host.
> 
> When gtk events occur through mouse moves, then
> the timeout is good (a 5 sec timeout) if no graphical
> activity exists, the timeout takes an average of 12 sec,
> even if there is console activity on the uml machine.

You're going to need to tell me what's happening at the system call
level - i.e. strace it and see what is doing something it shouldn't.

				Jeff

-- 
Work email - jdike at linux dot intel dot com

Re: [uml-devel] g_timeout_add

From: clowncoder <vincent-perrier@cl...> - 2008-02-14 22:16

With strace, when I do nothing on the gtk screen, we get
what is under, it seems that the poll has a 5000 milli-sec
timeout, but takes 10 sec to wake.

When I move the mouse on the gtk screen, there are too many
events on the screen to see anything but I can send it if you
need it.

gettimeofday({1203026980, 431960}, NULL) = 0
poll([{fd=3, events=POLLIN}], 1, 5000)  = 0
gettimeofday({1203026990, 459054}, NULL) = 0
gettimeofday({1203026990, 459250}, NULL) = 0
write(1, "1203026990\n", 111203026990
)            = 11
read(3, 0x809e004, 4096)                = -1 EAGAIN (Resource 
temporarily unavailable)
gettimeofday({1203026990, 459871}, NULL) = 0
poll([{fd=3, events=POLLIN}], 1, 5000)  = 0
gettimeofday({1203027000, 470939}, NULL) = 0
gettimeofday({1203027000, 471136}, NULL) = 0
write(1, "1203027000\n", 111203027000
)            = 11


Jeff Dike wrote:
> On Wed, Feb 13, 2008 at 08:57:20PM +0100, clowncoder wrote:
>   
>> It seems that g_timeout_add glib timeouts are not accurate
>> when there is no gtk activity on an uml target.
>>
>> This may be a glib problem since I cannot check
>> that it does not occur on my host.
>>
>> When gtk events occur through mouse moves, then
>> the timeout is good (a 5 sec timeout) if no graphical
>> activity exists, the timeout takes an average of 12 sec,
>> even if there is console activity on the uml machine.
>>     
>
> You're going to need to tell me what's happening at the system call
> level - i.e. strace it and see what is doing something it shouldn't.
>
> 				Jeff
>
>

Re: [uml-devel] g_timeout_add

From: Jeff Dike <jdike@ad...> - 2008-02-15 16:02

On Thu, Feb 14, 2008 at 11:16:45PM +0100, clowncoder wrote:
> With strace, when I do nothing on the gtk screen, we get
> what is under, it seems that the poll has a 5000 milli-sec
> timeout, but takes 10 sec to wake.

Can you show that with timestamps (strace -ttt)?

				Jeff

-- 
Work email - jdike at linux dot intel dot com

Re: [uml-devel] g_timeout_add

From: clowncoder <vincent-perrier@cl...> - 2008-02-15 17:39

Here it is:

By the way, do you use other very interresting tools such as strace?
if so could you give me names?



1203096910.892244 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 
2, 4994) = 0
1203096922.904300 gettimeofday({1203096922, 904988}, NULL) = 0
1203096922.905867 gettimeofday({1203096922, 906552}, NULL) = 0
1203096922.907449 write(1, "1203096922\n", 111203096922
) = 11
1203096922.909681 read(3, 0x809e004, 4096) = -1 EAGAIN (Resource 
temporarily unavailable)
1203096922.911270 gettimeofday({1203096922, 911946}, NULL) = 0
1203096922.912827 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 
2, 4994) = 0
1203096934.924538 gettimeofday({1203096934, 924926}, NULL) = 0
1203096934.925477 gettimeofday({1203096934, 925851}, NULL) = 0
1203096934.926400 write(1, "1203096934\n", 111203096934
) = 11
1203096934.927673 read(3, 0x809e004, 4096) = -1 EAGAIN (Resource 
temporarily unavailable)
1203096934.928613 gettimeofday({1203096934, 928937}, NULL) = 0
1203096934.929524 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 
2, 4996) = 0
1203096946.929030 gettimeofday({1203096946, 929420}, NULL) = 0
1203096946.929968 gettimeofday({1203096946, 930339}, NULL) = 0
1203096946.930882 write(1, "1203096946\n", 111203096946
) = 11
1203096946.932147 read(3, 0x809e004, 4096) = -1 EAGAIN (Resource 
temporarily unavailable)
1203096946.933062 gettimeofday({1203096946, 933422}, NULL) = 0
1203096946.933947 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 
2, 4996) = 0
1203096958.157856 gettimeofday({1203096958, 158538}, NULL) = 0
1203096958.159413 gettimeofday({1203096958, 160094}, NULL) = 0
1203096958.160992 write(1, "1203096958\n", 111203096958
) = 11


Jeff Dike wrote:
> On Thu, Feb 14, 2008 at 11:16:45PM +0100, clowncoder wrote:
>   
>> With strace, when I do nothing on the gtk screen, we get
>> what is under, it seems that the poll has a 5000 milli-sec
>> timeout, but takes 10 sec to wake.
>>     
>
> Can you show that with timestamps (strace -ttt)?
>
> 				Jeff
>
>

Re: [uml-devel] g_timeout_add

From: Jeff Dike <jdike@ad...> - 2008-02-15 18:47

On Fri, Feb 15, 2008 at 06:39:12PM +0100, clowncoder wrote:
> By the way, do you use other very interresting tools such as strace?
> if so could you give me names?

strace is the major one.

> 1203096946.933947 poll([{fd=3, events=POLLIN}, {fd=4, events=POLLIN}], 
> 2, 4996) = 0
> 1203096958.157856 gettimeofday({1203096958, 158538}, NULL) = 0

The smoking gun - a poll that should have timed out in .5 sec slept
for 12.

Now, can you do it again, but strace UML on the host at the same time,
with -ttt?

				Jeff

-- 
Work email - jdike at linux dot intel dot com

[uml-devel] Timeout in the select

From: clowncoder <vincent-perrier@cl...> - 2008-02-21 22:03

Hello,
At http://clownix.net, my new machine has the select timeout
problem, if you download it, the file 
/usr/src/clownix_liv_feb_2008/jeff_tst.c
in the virtual machine has a piece of software not behaving as
it should,  the 1 second timeout of the select is doubled.
Could you tell me if this is specific to my machine or if others
have the same problem.
Regards
Vincent Perrier

[uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly (was Re: g_timeout_add)

From: Nix <nix@es...> - 2008-03-14 23:02

On 15 Feb 2008, Jeff Dike told this:
> The smoking gun - a poll that should have timed out in .5 sec slept
> for 12.

FWIW this breaks all sorts of things, as one might expect: obviously it
breaks select() as well as poll(). For me the symptoms were a failure of
DHCP and spontaneous dropping off the net because lease renewal wasn't
happening in time (with 2.6.24.3, not with 2.6.24.2 that I can see).

The precise degree of oversleeping seems to depend on the clocksource in
use on the host (all hosts here are lightly loaded, running on 2.6.24.2
throughout these tests: select() does not wait for way too long
here). On a 1.4GHz Athlon IV using the tsc clocksource, I see consistent
oversleeps, but not enormous ones:

bash-3.2# ./select-sleep 1
Slept for 1 seconds.
bash-3.2# ./select-sleep 5
Slept for 7 seconds.
bash-3.2# ./select-sleep 5
Slept for 7 seconds.
bash-3.2# ./select-sleep 10
Slept for 13 seconds.
bash-3.2# ./select-sleep 30
Slept for 39 seconds.
bash-3.2# ./select-sleep 30
Slept for 39 seconds.
bash-3.2# ./select-sleep 60
Slept for 78 seconds.

On a 900MHz PIII using the pit clocksource (ick, why the hell isn't it
using tsc? oh, tsc unstable, how helpful) I see huge discrepancies,
still consistent, and interestingly all exactly four times as long as we
asked to sleep:

bash-3.2# ./select-sleep 1
Slept for 4 seconds.
bash-3.2# ./select-sleep 5
Slept for 20 seconds.
bash-3.2# ./select-sleep 5
Slept for 20 seconds.
bash-3.2# ./select-sleep 30
Slept for 120 seconds.
bash-3.2# ./select-sleep 30
Slept for 120 seconds.
bash-3.2# ./select-sleep 60
Slept for 240 seconds.


I'll do the -ttt UML tracing you requested next.


I'm testing using a little filesystem image containing a shell, glibc, and
this trivial obvious five-minute hack:

#define _POSIX_C_SOURCE 200112L

#include <stdio.h>
#include <stdlib.h>
#include <sys/select.h>
#include <sys/time.h>

int main (int argc, char *argv[])
 {
  long interval;
  struct timeval now;
  struct timeval timeout;
  struct timeval then;
  char *converr;
  fd_set foo;

  if (argc != 2)
   {
    fprintf (stderr, "Syntax: select-sleep INTERVAL\n");
    return 1;
   }

  interval = strtol (argv[1], &converr, 10);

  if (*converr != '\0')
   {
    fprintf (stderr, "Cannot convert %s to an integer\n", argv[1]);
    return 2;
   }

  gettimeofday (&then, NULL);
  timeout.tv_sec = interval;
  timeout.tv_usec = 0;

  FD_ZERO(&foo);
  select (0, NULL, NULL, NULL, &timeout);

  /* Watch me not care about not EINTR, I'm interested in *overlong* sleeps */

  gettimeofday (&now, NULL);

  fprintf (stderr, "Slept for %li seconds.\n", now.tv_sec - then.tv_sec);

  return 0;
 }

The UML's .config:

CONFIG_DEFCONFIG_LIST="arch/$ARCH/defconfig"
CONFIG_GENERIC_HARDIRQS=y
CONFIG_UML=y
CONFIG_MMU=y
CONFIG_NO_IOMEM=y
CONFIG_LOCKDEP_SUPPORT=y
CONFIG_GENERIC_CALIBRATE_DELAY=y
CONFIG_GENERIC_BUG=y
CONFIG_GENERIC_TIME=y
CONFIG_GENERIC_CLOCKEVENTS=y
CONFIG_IRQ_RELEASE_METHOD=y
CONFIG_MPENTIUMIII=y
CONFIG_X86_CMPXCHG=y
CONFIG_X86_L1_CACHE_SHIFT=5
CONFIG_X86_XADD=y
CONFIG_X86_WP_WORKS_OK=y
CONFIG_X86_INVLPG=y
CONFIG_X86_BSWAP=y
CONFIG_X86_POPAD_OK=y
CONFIG_X86_GOOD_APIC=y
CONFIG_X86_INTEL_USERCOPY=y
CONFIG_X86_USE_PPRO_CHECKSUM=y
CONFIG_X86_TSC=y
CONFIG_X86_CMOV=y
CONFIG_X86_MINIMUM_CPU_FAMILY=4
CONFIG_UML_X86=y
CONFIG_X86_32=y
CONFIG_RWSEM_XCHGADD_ALGORITHM=y
CONFIG_SEMAPHORE_SLEEPERS=y
CONFIG_HOST_VMSPLIT_3G=y
CONFIG_TOP_ADDR=0xC0000000
CONFIG_ARCH_HAS_SC_SIGNALS=y
CONFIG_ARCH_REUSE_HOST_VSYSCALL_AREA=y
CONFIG_GENERIC_HWEIGHT=y
CONFIG_SELECT_MEMORY_MODEL=y
CONFIG_FLATMEM_MANUAL=y
CONFIG_FLATMEM=y
CONFIG_FLAT_NODE_MEM_MAP=y
CONFIG_SPLIT_PTLOCK_CPUS=4
CONFIG_ZONE_DMA_FLAG=0
CONFIG_VIRT_TO_BUS=y
CONFIG_GENERIC_CLOCKEVENTS_BUILD=y
CONFIG_LD_SCRIPT_DYN=y
CONFIG_NET=y
CONFIG_BINFMT_ELF=y
CONFIG_MCONSOLE=y
CONFIG_NEST_LEVEL=0
CONFIG_KERNEL_STACK_ORDER=2
CONFIG_EXPERIMENTAL=y
CONFIG_BROKEN_ON_SMP=y
CONFIG_INIT_ENV_ARG_LIMIT=128
CONFIG_LOCALVERSION=""
CONFIG_SYSVIPC=y
CONFIG_SYSVIPC_SYSCTL=y
CONFIG_POSIX_MQUEUE=y
CONFIG_BSD_PROCESS_ACCT=y
CONFIG_LOG_BUF_SHIFT=14
CONFIG_FAIR_GROUP_SCHED=y
CONFIG_FAIR_USER_SCHED=y
CONFIG_RELAY=y
CONFIG_CC_OPTIMIZE_FOR_SIZE=y
CONFIG_SYSCTL=y
CONFIG_UID16=y
CONFIG_SYSCTL_SYSCALL=y
CONFIG_KALLSYMS=y
CONFIG_HOTPLUG=y
CONFIG_PRINTK=y
CONFIG_BUG=y
CONFIG_ELF_CORE=y
CONFIG_BASE_FULL=y
CONFIG_FUTEX=y
CONFIG_ANON_INODES=y
CONFIG_EPOLL=y
CONFIG_SIGNALFD=y
CONFIG_EVENTFD=y
CONFIG_SHMEM=y
CONFIG_VM_EVENT_COUNTERS=y
CONFIG_SLAB=y
CONFIG_SLABINFO=y
CONFIG_RT_MUTEXES=y
CONFIG_BASE_SMALL=0
CONFIG_BLOCK=y
CONFIG_BLK_DEV_IO_TRACE=y
CONFIG_IOSCHED_NOOP=y
CONFIG_IOSCHED_DEADLINE=y
CONFIG_DEFAULT_DEADLINE=y
CONFIG_DEFAULT_IOSCHED="deadline"
CONFIG_BLK_DEV=y
CONFIG_BLK_DEV_UBD=y
CONFIG_BLK_DEV_COW_COMMON=y
CONFIG_STDERR_CONSOLE=y
CONFIG_STDIO_CONSOLE=y
CONFIG_SSL=y
CONFIG_NULL_CHAN=y
CONFIG_PORT_CHAN=y
CONFIG_PTY_CHAN=y
CONFIG_TTY_CHAN=y
CONFIG_XTERM_CHAN=y
CONFIG_CON_ZERO_CHAN="fd:0,fd:1"
CONFIG_CON_CHAN="tty"
CONFIG_SSL_CHAN="pty"
CONFIG_UNIX98_PTYS=y
CONFIG_UML_RANDOM=y
CONFIG_UEVENT_HELPER_PATH="/sbin/hotplug"
CONFIG_STANDALONE=y
CONFIG_PREVENT_FIRMWARE_BUILD=y
CONFIG_PACKET=y
CONFIG_PACKET_MMAP=y
CONFIG_UNIX=y
CONFIG_INET=y
CONFIG_IP_MULTICAST=y
CONFIG_IP_ADVANCED_ROUTER=y
CONFIG_ASK_IP_FIB_HASH=y
CONFIG_IP_FIB_HASH=y
CONFIG_IP_MULTIPLE_TABLES=y
CONFIG_SYN_COOKIES=y
CONFIG_INET_DIAG=y
CONFIG_INET_TCP_DIAG=y
CONFIG_TCP_CONG_ADVANCED=y
CONFIG_TCP_CONG_CUBIC=y
CONFIG_DEFAULT_CUBIC=y
CONFIG_DEFAULT_TCP_CONG="cubic"
CONFIG_NETFILTER=y
CONFIG_NF_CONNTRACK_ENABLED=y
CONFIG_NF_CONNTRACK=y
CONFIG_NF_CT_ACCT=y
CONFIG_NF_CONNTRACK_MARK=y
CONFIG_NF_CT_PROTO_UDPLITE=y
CONFIG_NF_CONNTRACK_FTP=y
CONFIG_NF_CONNTRACK_IRC=y
CONFIG_NF_CONNTRACK_SIP=y
CONFIG_NETFILTER_XTABLES=y
CONFIG_NETFILTER_XT_TARGET_CLASSIFY=y
CONFIG_NETFILTER_XT_TARGET_MARK=y
CONFIG_NETFILTER_XT_TARGET_NFQUEUE=y
CONFIG_NETFILTER_XT_MATCH_CONNLIMIT=y
CONFIG_NETFILTER_XT_MATCH_CONNMARK=y
CONFIG_NETFILTER_XT_MATCH_HELPER=y
CONFIG_NETFILTER_XT_MATCH_LIMIT=y
CONFIG_NETFILTER_XT_MATCH_MARK=y
CONFIG_NETFILTER_XT_MATCH_MULTIPORT=y
CONFIG_NETFILTER_XT_MATCH_QUOTA=y
CONFIG_NETFILTER_XT_MATCH_STATE=y
CONFIG_NETFILTER_XT_MATCH_HASHLIMIT=y
CONFIG_NF_CONNTRACK_IPV4=y
CONFIG_NF_CONNTRACK_PROC_COMPAT=y
CONFIG_IP_NF_IPTABLES=y
CONFIG_IP_NF_MATCH_IPRANGE=y
CONFIG_IP_NF_MATCH_TOS=y
CONFIG_IP_NF_MATCH_RECENT=y
CONFIG_IP_NF_MATCH_OWNER=y
CONFIG_IP_NF_MATCH_ADDRTYPE=y
CONFIG_IP_NF_FILTER=y
CONFIG_IP_NF_TARGET_REJECT=y
CONFIG_IP_NF_TARGET_LOG=y
CONFIG_NF_NAT=y
CONFIG_NF_NAT_NEEDED=y
CONFIG_IP_NF_TARGET_REDIRECT=y
CONFIG_NF_NAT_FTP=y
CONFIG_NF_NAT_IRC=y
CONFIG_NF_NAT_SIP=y
CONFIG_IP_NF_MANGLE=y
CONFIG_IP_NF_TARGET_TOS=y
CONFIG_IP_NF_TARGET_ECN=y
CONFIG_NET_SCHED=y
CONFIG_NET_SCH_CBQ=y
CONFIG_NET_SCH_HTB=y
CONFIG_NET_SCH_HFSC=y
CONFIG_NET_SCH_PRIO=y
CONFIG_NET_SCH_RED=y
CONFIG_NET_SCH_SFQ=y
CONFIG_NET_SCH_TEQL=y
CONFIG_NET_SCH_TBF=y
CONFIG_NET_SCH_GRED=y
CONFIG_NET_SCH_DSMARK=y
CONFIG_NET_SCH_INGRESS=y
CONFIG_NET_CLS=y
CONFIG_NET_CLS_BASIC=y
CONFIG_NET_CLS_TCINDEX=y
CONFIG_NET_CLS_ROUTE4=y
CONFIG_NET_CLS_ROUTE=y
CONFIG_NET_CLS_FW=y
CONFIG_NET_CLS_U32=y
CONFIG_CLS_U32_PERF=y
CONFIG_CLS_U32_MARK=y
CONFIG_NET_CLS_RSVP=y
CONFIG_NET_EMATCH=y
CONFIG_NET_EMATCH_STACK=32
CONFIG_NET_EMATCH_CMP=y
CONFIG_NET_EMATCH_NBYTE=y
CONFIG_NET_EMATCH_U32=y
CONFIG_NET_EMATCH_META=y
CONFIG_NET_CLS_ACT=y
CONFIG_NET_ACT_POLICE=y
CONFIG_NET_ACT_GACT=y
CONFIG_NET_ACT_PEDIT=y
CONFIG_NET_SCH_FIFO=y
CONFIG_FIB_RULES=y
CONFIG_UML_NET=y
CONFIG_UML_NET_TUNTAP=y
CONFIG_NETDEVICES=y
CONFIG_DUMMY=y
CONFIG_TUN=y
CONFIG_EXT2_FS=y
CONFIG_EXT2_FS_XATTR=y
CONFIG_EXT2_FS_POSIX_ACL=y
CONFIG_EXT2_FS_SECURITY=y
CONFIG_FS_MBCACHE=y
CONFIG_FS_POSIX_ACL=y
CONFIG_INOTIFY=y
CONFIG_INOTIFY_USER=y
CONFIG_QUOTA=y
CONFIG_PRINT_QUOTA_WARNING=y
CONFIG_QUOTACTL=y
CONFIG_DNOTIFY=y
CONFIG_GENERIC_ACL=y
CONFIG_PROC_FS=y
CONFIG_PROC_SYSCTL=y
CONFIG_SYSFS=y
CONFIG_TMPFS=y
CONFIG_TMPFS_POSIX_ACL=y
CONFIG_CONFIGFS_FS=y
CONFIG_NETWORK_FILESYSTEMS=y
CONFIG_NFS_FS=y
CONFIG_NFS_V3=y
CONFIG_NFS_V3_ACL=y
CONFIG_LOCKD=y
CONFIG_LOCKD_V4=y
CONFIG_NFS_ACL_SUPPORT=y
CONFIG_NFS_COMMON=y
CONFIG_SUNRPC=y
CONFIG_MSDOS_PARTITION=y
CONFIG_KEYS=y
CONFIG_SECURITY=y
CONFIG_SECURITY_CAPABILITIES=y
CONFIG_SECURITY_FILE_CAPABILITIES=y
CONFIG_CRYPTO=y
CONFIG_CRYPTO_ALGAPI=y
CONFIG_CRYPTO_MANAGER=y
CONFIG_CRYPTO_SHA1=y
CONFIG_BITREVERSE=y
CONFIG_CRC32=y
CONFIG_PLIST=y
CONFIG_HAS_DMA=y
CONFIG_INSTRUMENTATION=y
CONFIG_ENABLE_WARN_DEPRECATED=y
CONFIG_ENABLE_MUST_CHECK=y
CONFIG_DEBUG_FS=y
CONFIG_DEBUG_BUGVERBOSE=y

Re: [uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly (was Re: g_timeout_add)

From: Jeff Dike <jdike@ad...> - 2008-03-17 16:27

On Fri, Mar 14, 2008 at 11:01:35PM +0000, Nix wrote:
> On a 1.4GHz Athlon IV using the tsc clocksource, I see consistent
> oversleeps, but not enormous ones:

> bash-3.2# ./select-sleep 10
> Slept for 13 seconds.

I'm seeing the same thing with tickless disabled on current UML - stay
tuned...

				Jeff

-- 
Work email - jdike at linux dot intel dot com

Re: [uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly (was Re: g_timeout_add)

From: Jeff Dike <jdike@ad...> - 2008-03-17 17:03

On Fri, Mar 14, 2008 at 11:01:35PM +0000, Nix wrote:
> bash-3.2# ./select-sleep 10
> Slept for 13 seconds.

See what kind of difference the patch below makes - it reduces the 30%
oversleeping down to 10% for me.  That's still way too much, but it's
better.

The problem being fixed here is that setitimer consistently returns a
remaining time greater than what was originally requested, by ~20%:

1205773032.413780 setitimer(ITIMER_VIRTUAL, {it_interval={0, 10000}, it_value={0, 10000}}, NULL) = 0
1205773032.413814 setitimer(ITIMER_VIRTUAL, {it_interval={0, 0},
it_value={0, 0}}, {it_interval={0, 10998}, it_value={0, 11998}}) = 0

This is setting a 100 HZ timer, immediately followed by a cancellation
which also requests the amount left on the timer.  The interval is
rounded up by 10%, and the first tick by 20%.

	       	       	    Jeff

-- 
Work email - jdike at linux dot intel dot com

Index: linux-2.6.22/arch/um/os-Linux/time.c
===================================================================
--- linux-2.6.22.orig/arch/um/os-Linux/time.c	2008-02-18 11:53:51.000000000 -0500
+++ linux-2.6.22/arch/um/os-Linux/time.c	2008-03-17 12:55:41.000000000 -0400
@@ -58,12 +58,17 @@ static inline long long timeval_to_ns(co
 long long disable_timer(void)
 {
 	struct itimerval time = ((struct itimerval) { { 0, 0 }, { 0, 0 } });
+	int remain, max = UM_NSEC_PER_SEC / UM_HZ;
 
 	if (setitimer(ITIMER_VIRTUAL, &time, &time) < 0)
 		printk(UM_KERN_ERR "disable_timer - setitimer failed, "
 		       "errno = %d\n", errno);
 
-	return timeval_to_ns(&time.it_value);
+	remain = timeval_to_ns(&time.it_value);
+	if (remain > max)
+		remain = max;
+
+	return remain;
 }
 
 long long os_nsecs(void)

Re: [uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly (was Re: g_timeout_add)

From: Jeff Dike <jdike@ad...> - 2008-03-17 19:34

Below is the same patch with another kluge, which cuts down the
requested sleep by 10% in hopes of getting the actual sleep closer to
what's wanted.

This is unusable in anything resembling mainline, but I'd like to see
how your various systems react to it.  I'm getting very close to the
sleeps I asked for (with slight undersleeping, which is a bug).

       	       	   Jeff

-- 
Work email - jdike at linux dot intel dot com

Index: linux-2.6.22/arch/um/os-Linux/time.c
===================================================================
--- linux-2.6.22.orig/arch/um/os-Linux/time.c	2008-02-18 11:53:51.000000000 -0500
+++ linux-2.6.22/arch/um/os-Linux/time.c	2008-03-17 15:11:51.000000000 -0400
@@ -58,12 +58,17 @@ static inline long long timeval_to_ns(co
 long long disable_timer(void)
 {
 	struct itimerval time = ((struct itimerval) { { 0, 0 }, { 0, 0 } });
+	int remain, max = UM_NSEC_PER_SEC / UM_HZ;
 
 	if (setitimer(ITIMER_VIRTUAL, &time, &time) < 0)
 		printk(UM_KERN_ERR "disable_timer - setitimer failed, "
 		       "errno = %d\n", errno);
 
-	return timeval_to_ns(&time.it_value);
+	remain = timeval_to_ns(&time.it_value);
+	if (remain > max)
+		remain = max;
+
+	return remain;
 }
 
 long long os_nsecs(void)
@@ -126,6 +131,8 @@ void idle_sleep(unsigned long long nsecs
 	 */
 	if (nsecs == 0)
 		nsecs = UM_NSEC_PER_SEC / UM_HZ;
+
+	nsecs = nsecs * 9 / 10;
 	ts = ((struct timespec) { .tv_sec	= nsecs / UM_NSEC_PER_SEC,
 				  .tv_nsec	= nsecs % UM_NSEC_PER_SEC });

Re: [uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly

From: Nix <nix@es...> - 2008-03-17 21:08

On 17 Mar 2008, Jeff Dike verbalised:

> Below is the same patch with another kluge, which cuts down the
> requested sleep by 10% in hopes of getting the actual sleep closer to
> what's wanted.

Eeuuuuw. :)

> This is unusable in anything resembling mainline, but I'd like to see
> how your various systems react to it.  I'm getting very close to the
> sleeps I asked for (with slight undersleeping, which is a bug).

OK.

Tests on host with clocksource pit:

bash-3.2# bin/select-sleep 5
Slept for 5 seconds.
bash-3.2# bin/select-sleep 10
Slept for 11 seconds.
bash-3.2# bin/select-sleep 30
Slept for 31 seconds.
bash-3.2# bin/select-sleep 60
Slept for 61 seconds.

... so much better than the 4x error without this patch.

Tests on host with clocksource tsc:

bash-3.2# bin/select-sleep 5
Slept for 5 seconds.
bash-3.2# bin/select-sleep 10
Slept for 10 seconds.
bash-3.2# bin/select-sleep 30
Slept for 30 seconds.
bash-3.2# bin/select-sleep 60
Slept for 61 seconds.

Distinctly better than without this patch.

(Am I the only person who finds it strange that (some) clocksource
hackers are arguing about accuracy problems in the ppm range while we're
glad to get an error of `only' single seconds per minute out of it? 
Maybe next year we can invent the `pendulum' clocksource :) )

-- 
`The rest is a tale of post and counter-post.' --- Ian Rawlings
                                                   describes USENET

Re: [uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly

From: Jeff Dike <jdike@ad...> - 2008-03-18 17:00

Below is another patch.

I was hurt and disappointed by your
> Eeuuuuw. :)
so I got rid of the 9/10 thing.

This version keeps track of the time between ticks (as reported by the
host's gettimeofday) and adjusts its sleeping and reporting ticks
accordingly.

It's still undersleeping a little - your little test once reported 19
seconds for a 20 second sleep.  Otherwise, it's reporting sleep times
that are right on the money.

				Jeff

-- 
Work email - jdike at linux dot intel dot com

Index: linux-2.6.22/arch/um/os-Linux/time.c
===================================================================
--- linux-2.6.22.orig/arch/um/os-Linux/time.c	2008-03-18 12:32:19.000000000 -0400
+++ linux-2.6.22/arch/um/os-Linux/time.c	2008-03-18 12:45:50.000000000 -0400
@@ -11,6 +11,7 @@
 #include "kern_constants.h"
 #include "os.h"
 #include "user.h"
+#include "kern_util.h"
 
 int set_interval(void)
 {
@@ -58,12 +59,17 @@ static inline long long timeval_to_ns(co
 long long disable_timer(void)
 {
 	struct itimerval time = ((struct itimerval) { { 0, 0 }, { 0, 0 } });
+	int remain, max = UM_NSEC_PER_SEC / UM_HZ;
 
 	if (setitimer(ITIMER_VIRTUAL, &time, &time) < 0)
 		printk(UM_KERN_ERR "disable_timer - setitimer failed, "
 		       "errno = %d\n", errno);
 
-	return timeval_to_ns(&time.it_value);
+	remain = timeval_to_ns(&time.it_value);
+	if (remain > max)
+		remain = max;
+
+	return remain;
 }
 
 long long os_nsecs(void)
@@ -79,7 +85,47 @@ static int after_sleep_interval(struct t
 {
 	return 0;
 }
+
+
+static void deliver_alarm(void)
+{
+	alarm_handler(SIGVTALRM, NULL);
+}
+
+static unsigned long long sleep_time(unsigned long long nsecs)
+{
+	return nsecs;
+}
+
 #else
+unsigned long long last_tick;
+unsigned long long skew;
+
+extern void alarm_handler(int sig, struct sigcontext *sc);
+
+static void deliver_alarm(void)
+{
+	unsigned long long this_tick = os_nsecs();
+	int one_tick = UM_NSEC_PER_SEC / UM_HZ;
+
+	if (last_tick == 0)
+		last_tick = this_tick - one_tick;
+
+	skew += this_tick - last_tick;
+
+	while (skew >= one_tick) {
+		alarm_handler(SIGVTALRM, NULL);
+		skew -= one_tick;
+	}
+
+	last_tick = this_tick;
+}
+
+static unsigned long long sleep_time(unsigned long long nsecs)
+{
+	return nsecs > skew ? nsecs - skew : 0;
+}
+
 static inline long long timespec_to_us(const struct timespec *ts)
 {
 	return ((long long) ts->tv_sec * UM_USEC_PER_SEC) +
@@ -102,6 +148,8 @@ static int after_sleep_interval(struct t
 	 */
 	if (start_usecs > usec)
 		start_usecs = usec;
+
+	start_usecs -= skew / UM_NSEC_PER_USEC;
 	tv = ((struct timeval) { .tv_sec  = start_usecs / UM_USEC_PER_SEC,
 				 .tv_usec = start_usecs % UM_USEC_PER_SEC });
 	interval = ((struct itimerval) { { 0, usec }, tv });
@@ -113,8 +161,6 @@ static int after_sleep_interval(struct t
 }
 #endif
 
-extern void alarm_handler(int sig, struct sigcontext *sc);
-
 void idle_sleep(unsigned long long nsecs)
 {
 	struct timespec ts;
@@ -126,10 +172,12 @@ void idle_sleep(unsigned long long nsecs
 	 */
 	if (nsecs == 0)
 		nsecs = UM_NSEC_PER_SEC / UM_HZ;
+
+	nsecs = sleep_time(nsecs);
 	ts = ((struct timespec) { .tv_sec	= nsecs / UM_NSEC_PER_SEC,
 				  .tv_nsec	= nsecs % UM_NSEC_PER_SEC });
 
 	if (nanosleep(&ts, &ts) == 0)
-		alarm_handler(SIGVTALRM, NULL);
+		deliver_alarm();
 	after_sleep_interval(&ts);
 }

Re: [uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly

From: Nix <nix@es...> - 2008-03-18 19:39

On 18 Mar 2008, Jeff Dike outgrape:

> Below is another patch.
>
> I was hurt and disappointed by your
>> Eeuuuuw. :)
> so I got rid of the 9/10 thing.

Yay! That's much less dependent on the exact nature of whatever the
underlying bug is :) a random 9/10, well, it just makes my skin itch
even if it does work (unless there turned out to be a fundamental reason
why 9/10 was the right value, that is).

> This version keeps track of the time between ticks (as reported by the
> host's gettimeofday) and adjusts its sleeping and reporting ticks
> accordingly.
>
> It's still undersleeping a little - your little test once reported 19
> seconds for a 20 second sleep.  Otherwise, it's reporting sleep times
> that are right on the money.

I think we can live with that. Expecting perfect accuracy, even in a
sleep, is hopeless unless we're niced to realtime priority in any case,
and this looks like it should automatically adapt to varying load on
the host as well, which is really quite neat.

I'll give it an acid test (does ISC dhclient work now?) in a few hours,
when I can afford to drop offline.

-- 
`The rest is a tale of post and counter-post.' --- Ian Rawlings
                                                   describes USENET

Re: [uml-devel] [2.6.24.x] UML select()/poll() oversleeping reproducibly

From: Nix <nix@es...> - 2008-03-19 22:14

On 18 Mar 2008, Jeff Dike told this:
> This version keeps track of the time between ticks (as reported by the
> host's gettimeofday) and adjusts its sleeping and reporting ticks
> accordingly.

I can confirm that, as expected, this patch works well enough that
timing problems don't break dhclient anymore (which requires a 2x
oversleep, which you're a long way from now).

At last I can upgrade my firewall :)

-- 
`The rest is a tale of post and counter-post.' --- Ian Rawlings
                                                   describes USENET