Re: round_jiffies and load average

2007-03-01 Thread Simon Arlott 
On 24/02/07 15:19, Simon Arlott wrote:
> I've modified the driver of an USB device (cxacru) to schedule the next poll
> for status every 1s using round_jiffies_relative instead of just waiting 1s
> since the last poll was completed. This process takes on average 11ms to
> complete and while it is waiting for a response it's considered running.
> The load average is calculated every 5 seconds equivalent to round_jiffies,
> so I have a problem with the load average always tending towards 1.00.
> Perhaps the load average count could be run just before or in the middle of
> a second instead?

I've added some printks to show exactly what happens (see below).

Since calc_load() appears to be run as often as possible, would it be ok to 
move it to run half a second out of step from rounded jiffies? Its count 
value is initialised to LOAD_FREQ so it would be easy to add HZ/2.

Otherwise every process using round_jiffies to 1s (1.00), 2s (0.50), 
3s (0.33), 4s (0.25), 5s (0.00 or 1.00) could affect the load average in a 
constant way. (Beyond 10s the effect is unlikely to be noticed).


After a while of this (~3min):
[  192.147049] cxacru_poll_status(..), jiffies=4294832000
[  192.151319] cxacru_poll_status(..), jiffies=4294832004, next=996
[  192.463459] calc_load(27), count=-20, jiffies=4294832316
[  192.463472] calc_load(27), count=4980, jiffies=4294832316

Jiffies wraps:
[  327.121469] cxacru_poll_status(..), jiffies=4294967000
[  327.139428] cxacru_poll_status(..), jiffies=4294967018, next=1000
[  327.437739] calc_load(27), count=-20, jiffies=20
[  327.437750] calc_load(27), count=4980, jiffies=20

The next run occurs during cxacru_poll_status:
[  332.416288] cxacru_poll_status(..), jiffies=5000
[  332.417312] calc_load(1), count=-1, jiffies=5001
[  332.417322] calc_load(1), count=4999, jiffies=5001
[  332.423382] cxacru_poll_status(..), jiffies=5007, next=993

This happens without fail until I reboot:
[  672.350970] cxacru_poll_status(..), jiffies=345000
[  672.351913] calc_load(1), count=-1, jiffies=345001
[  672.351926] calc_load(1), count=4999, jiffies=345001
[  672.367737] cxacru_poll_status(..), jiffies=345016, next=984


It's interesting that calc_load() is run most of the time 19ms later 
(count=-20) than usual until jiffies wraps, then it runs on time or 1ms late 
(count=-2). Full log available on request (75K), HZ=1000 with NO_HZ.


(diff below of cxacru.c based on http://lkml.org/lkml/2007/2/23/328)
---
diff --git a/drivers/usb/atm/cxacru.c b/drivers/usb/atm/cxacru.c
index c8b69bf..4717fa4 100644
--- a/drivers/usb/atm/cxacru.c
+++ b/drivers/usb/atm/cxacru.c
@@ -535,6 +535,7 @@ static void cxacru_poll_status(struct work_struct *work)
struct atm_dev *atm_dev = usbatm->atm_dev;
int ret;
 
+   printk(KERN_DEBUG "cxacru_poll_status(..), jiffies=%lu\n", jiffies);
ret = cxacru_cm_get_array(instance, CM_REQUEST_CARD_INFO_GET, buf, 
CXINF_MAX);
if (ret < 0) {
atm_warn(usbatm, "poll status: error %d\n", ret);
@@ -599,6 +600,8 @@ static void cxacru_poll_status(struct work_struct *work)
 reschedule:
schedule_delayed_work(>poll_work,

round_jiffies_relative(msecs_to_jiffies(POLL_INTERVAL*1000)));
+   printk(KERN_DEBUG "cxacru_poll_status(..), jiffies=%lu, next=%lu\n", 
jiffies, 
+   round_jiffies_relative(msecs_to_jiffies(POLL_INTERVAL*1000)));
 }
 
 static int cxacru_fw(struct usb_device *usb_dev, enum cxacru_fw_request fw,
diff --git a/kernel/timer.c b/kernel/timer.c
index cb1b86a..9c2b816 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -1230,12 +1230,14 @@ static inline void calc_load(unsigned long ticks)
count -= ticks;
if (unlikely(count < 0)) {
active_tasks = count_active_tasks();
+   printk(KERN_DEBUG "calc_load(%lu), count=%d, jiffies=%lu\n", 
ticks, count, jiffies);
do {
CALC_LOAD(avenrun[0], EXP_1, active_tasks);
CALC_LOAD(avenrun[1], EXP_5, active_tasks);
CALC_LOAD(avenrun[2], EXP_15, active_tasks);
count += LOAD_FREQ;
} while (count < 0);
+   printk(KERN_DEBUG "calc_load(%lu), count=%d, jiffies=%lu\n", 
ticks, count, jiffies);
}
 }

 

-- 
Simon Arlott
-
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/

Re: round_jiffies and load average

2007-03-01 Thread Simon Arlott 
On 24/02/07 15:19, Simon Arlott wrote:
 I've modified the driver of an USB device (cxacru) to schedule the next poll
 for status every 1s using round_jiffies_relative instead of just waiting 1s
 since the last poll was completed. This process takes on average 11ms to
 complete and while it is waiting for a response it's considered running.
 The load average is calculated every 5 seconds equivalent to round_jiffies,
 so I have a problem with the load average always tending towards 1.00.
 Perhaps the load average count could be run just before or in the middle of
 a second instead?

I've added some printks to show exactly what happens (see below).

Since calc_load() appears to be run as often as possible, would it be ok to 
move it to run half a second out of step from rounded jiffies? Its count 
value is initialised to LOAD_FREQ so it would be easy to add HZ/2.

Otherwise every process using round_jiffies to 1s (1.00), 2s (0.50), 
3s (0.33), 4s (0.25), 5s (0.00 or 1.00) could affect the load average in a 
constant way. (Beyond 10s the effect is unlikely to be noticed).


After a while of this (~3min):
[  192.147049] cxacru_poll_status(..), jiffies=4294832000
[  192.151319] cxacru_poll_status(..), jiffies=4294832004, next=996
[  192.463459] calc_load(27), count=-20, jiffies=4294832316
[  192.463472] calc_load(27), count=4980, jiffies=4294832316

Jiffies wraps:
[  327.121469] cxacru_poll_status(..), jiffies=4294967000
[  327.139428] cxacru_poll_status(..), jiffies=4294967018, next=1000
[  327.437739] calc_load(27), count=-20, jiffies=20
[  327.437750] calc_load(27), count=4980, jiffies=20

The next run occurs during cxacru_poll_status:
[  332.416288] cxacru_poll_status(..), jiffies=5000
[  332.417312] calc_load(1), count=-1, jiffies=5001
[  332.417322] calc_load(1), count=4999, jiffies=5001
[  332.423382] cxacru_poll_status(..), jiffies=5007, next=993

This happens without fail until I reboot:
[  672.350970] cxacru_poll_status(..), jiffies=345000
[  672.351913] calc_load(1), count=-1, jiffies=345001
[  672.351926] calc_load(1), count=4999, jiffies=345001
[  672.367737] cxacru_poll_status(..), jiffies=345016, next=984


It's interesting that calc_load() is run most of the time 19ms later 
(count=-20) than usual until jiffies wraps, then it runs on time or 1ms late 
(count=-2). Full log available on request (75K), HZ=1000 with NO_HZ.


(diff below of cxacru.c based on http://lkml.org/lkml/2007/2/23/328)
---
diff --git a/drivers/usb/atm/cxacru.c b/drivers/usb/atm/cxacru.c
index c8b69bf..4717fa4 100644
--- a/drivers/usb/atm/cxacru.c
+++ b/drivers/usb/atm/cxacru.c
@@ -535,6 +535,7 @@ static void cxacru_poll_status(struct work_struct *work)
struct atm_dev *atm_dev = usbatm-atm_dev;
int ret;
 
+   printk(KERN_DEBUG cxacru_poll_status(..), jiffies=%lu\n, jiffies);
ret = cxacru_cm_get_array(instance, CM_REQUEST_CARD_INFO_GET, buf, 
CXINF_MAX);
if (ret  0) {
atm_warn(usbatm, poll status: error %d\n, ret);
@@ -599,6 +600,8 @@ static void cxacru_poll_status(struct work_struct *work)
 reschedule:
schedule_delayed_work(instance-poll_work,

round_jiffies_relative(msecs_to_jiffies(POLL_INTERVAL*1000)));
+   printk(KERN_DEBUG cxacru_poll_status(..), jiffies=%lu, next=%lu\n, 
jiffies, 
+   round_jiffies_relative(msecs_to_jiffies(POLL_INTERVAL*1000)));
 }
 
 static int cxacru_fw(struct usb_device *usb_dev, enum cxacru_fw_request fw,
diff --git a/kernel/timer.c b/kernel/timer.c
index cb1b86a..9c2b816 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -1230,12 +1230,14 @@ static inline void calc_load(unsigned long ticks)
count -= ticks;
if (unlikely(count  0)) {
active_tasks = count_active_tasks();
+   printk(KERN_DEBUG calc_load(%lu), count=%d, jiffies=%lu\n, 
ticks, count, jiffies);
do {
CALC_LOAD(avenrun[0], EXP_1, active_tasks);
CALC_LOAD(avenrun[1], EXP_5, active_tasks);
CALC_LOAD(avenrun[2], EXP_15, active_tasks);
count += LOAD_FREQ;
} while (count  0);
+   printk(KERN_DEBUG calc_load(%lu), count=%d, jiffies=%lu\n, 
ticks, count, jiffies);
}
 }

 

-- 
Simon Arlott
-
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/

round_jiffies and load average

2007-02-24 Thread Simon Arlott 
I've modified the driver of an USB device (cxacru) to schedule the next poll 
for status every 1s using round_jiffies_relative instead of just waiting 1s 
since the last poll was completed. This process takes on average 11ms to 
complete and while it is waiting for a response it's considered running.

The load average is calculated every 5 seconds equivalent to round_jiffies, so 
I have a problem with the load average always tending towards 1.00:

 14:26:19 up 6 days, 14:45,  5 users,  load average: 1.10, 1.04, 1.02
 14:27:19 up 6 days, 14:46,  5 users,  load average: 1.03, 1.03, 1.01
 14:28:19 up 6 days, 14:47,  5 users,  load average: 0.95, 1.01, 1.00
 14:29:19 up 6 days, 14:48,  5 users,  load average: 0.90, 0.97, 0.99
 14:30:19 up 6 days, 14:49,  5 users,  load average: 0.93, 0.96, 0.98
 14:31:19 up 6 days, 14:50,  5 users,  load average: 0.90, 0.94, 0.97
 14:32:20 up 6 days, 14:51,  5 users,  load average: 0.96, 0.95, 0.97
 14:33:20 up 6 days, 14:52,  5 users,  load average: 0.98, 0.95, 0.97
 14:34:20 up 6 days, 14:53,  5 users,  load average: 1.09, 0.99, 0.98
 14:35:20 up 6 days, 14:54,  5 users,  load average: 1.03, 0.99, 0.98
 14:36:20 up 6 days, 14:55,  5 users,  load average: 1.01, 0.99, 0.98
 14:37:20 up 6 days, 14:56,  5 users,  load average: 1.00, 0.99, 0.98
 14:38:21 up 6 days, 14:57,  5 users,  load average: 1.22, 1.05, 1.00
 14:39:21 up 6 days, 14:58,  5 users,  load average: 1.08, 1.04, 1.00
 14:40:21 up 6 days, 14:59,  5 users,  load average: 1.03, 1.03, 1.00
 14:41:21 up 6 days, 15:00,  5 users,  load average: 0.95, 1.01, 0.99
 14:42:21 up 6 days, 15:01,  5 users,  load average: 0.90, 0.97, 0.98
 14:43:21 up 6 days, 15:02,  5 users,  load average: 0.99, 0.99, 0.99
 14:44:22 up 6 days, 15:03,  5 users,  load average: 0.86, 0.94, 0.97
 14:45:22 up 6 days, 15:04,  5 users,  load average: 0.97, 0.95, 0.97
 14:46:22 up 6 days, 15:05,  5 users,  load average: 1.08, 0.99, 0.98
 14:47:22 up 6 days, 15:06,  5 users,  load average: 1.03, 0.99, 0.98
 14:48:22 up 6 days, 15:07,  5 users,  load average: 1.32, 1.07, 1.01

Perhaps the load average count could be run just before or in the middle of a 
second instead?

-- 
Simon Arlott



signature.asc
Description: OpenPGP digital signature

round_jiffies and load average

2007-02-24 Thread Simon Arlott 
I've modified the driver of an USB device (cxacru) to schedule the next poll 
for status every 1s using round_jiffies_relative instead of just waiting 1s 
since the last poll was completed. This process takes on average 11ms to 
complete and while it is waiting for a response it's considered running.

The load average is calculated every 5 seconds equivalent to round_jiffies, so 
I have a problem with the load average always tending towards 1.00:

 14:26:19 up 6 days, 14:45,  5 users,  load average: 1.10, 1.04, 1.02
 14:27:19 up 6 days, 14:46,  5 users,  load average: 1.03, 1.03, 1.01
 14:28:19 up 6 days, 14:47,  5 users,  load average: 0.95, 1.01, 1.00
 14:29:19 up 6 days, 14:48,  5 users,  load average: 0.90, 0.97, 0.99
 14:30:19 up 6 days, 14:49,  5 users,  load average: 0.93, 0.96, 0.98
 14:31:19 up 6 days, 14:50,  5 users,  load average: 0.90, 0.94, 0.97
 14:32:20 up 6 days, 14:51,  5 users,  load average: 0.96, 0.95, 0.97
 14:33:20 up 6 days, 14:52,  5 users,  load average: 0.98, 0.95, 0.97
 14:34:20 up 6 days, 14:53,  5 users,  load average: 1.09, 0.99, 0.98
 14:35:20 up 6 days, 14:54,  5 users,  load average: 1.03, 0.99, 0.98
 14:36:20 up 6 days, 14:55,  5 users,  load average: 1.01, 0.99, 0.98
 14:37:20 up 6 days, 14:56,  5 users,  load average: 1.00, 0.99, 0.98
 14:38:21 up 6 days, 14:57,  5 users,  load average: 1.22, 1.05, 1.00
 14:39:21 up 6 days, 14:58,  5 users,  load average: 1.08, 1.04, 1.00
 14:40:21 up 6 days, 14:59,  5 users,  load average: 1.03, 1.03, 1.00
 14:41:21 up 6 days, 15:00,  5 users,  load average: 0.95, 1.01, 0.99
 14:42:21 up 6 days, 15:01,  5 users,  load average: 0.90, 0.97, 0.98
 14:43:21 up 6 days, 15:02,  5 users,  load average: 0.99, 0.99, 0.99
 14:44:22 up 6 days, 15:03,  5 users,  load average: 0.86, 0.94, 0.97
 14:45:22 up 6 days, 15:04,  5 users,  load average: 0.97, 0.95, 0.97
 14:46:22 up 6 days, 15:05,  5 users,  load average: 1.08, 0.99, 0.98
 14:47:22 up 6 days, 15:06,  5 users,  load average: 1.03, 0.99, 0.98
 14:48:22 up 6 days, 15:07,  5 users,  load average: 1.32, 1.07, 1.01

Perhaps the load average count could be run just before or in the middle of a 
second instead?

-- 
Simon Arlott



signature.asc
Description: OpenPGP digital signature