Solved tick value < 0? unsigned long negative in printf?

C

cmoerz

Got a question about printk/printf - preferably in kernel level, but printf(3)() should likely help as well.

I got some C code that does some arithmetic with the apparently static "tick" variable in the kernel. I haven't found the definition (yet), but I suppose it's u64. However, somehow, when I printf the vlaue with "%llu" I get a negative number.

What am I doing wrong here?

Example:
Code: 
unsigned long long tmp_jiffies;
tmp_jiffies = jiffies; //jiffies is a define jiffies ticks
printf("tmp_jiffies = %llu", tmp_jiffies);

I am getting as result: tmp_jiffies = -2146056371

Not sure, how that's even possible??? Even an overflow should be positive, I'd assume?
 
cmoerz said:
Even an overflow should be positive, I'd assume?
Click to expand...
Yes, it should be. I've never seen %u print negative numbers no matter what size is specified.
Is the code you shared actual snippet or you pasted the simple version of it? Are you 100% sure what you read is the code you've seen?

I tried a dummy test - loaded a kernel module with code you mentioned and I got expected results:
Code: 
 case MOD_LOAD:
    unsigned long long i = -2146056371ULL;
    printf("i: %llu\n", i);
Code: 
i: 18446744071563495245

I could think of a problem when somebody assigned constant without proper ULL in the end and hence converting it to int but still, I don't understand how negative number was printed.
 
Well, I don't get it either. Here's the full method with a bunch of DEBUG code:
Code: 
/*
 * If you need to wait X milliseconds between events A and B, but event B
 * doesn't happen exactly after event A, you record the timestamp (jiffies) of
 * when event A happened, then just before event B you call this function and
 * pass the timestamp as the first argument, and X as the second argument.
 */
static inline void
wait_remaining_ms_from_jiffies(unsigned long timestamp_jiffies, int to_wait_ms)
{
#ifdef __linux__
    unsigned long target_jiffies, tmp_jiffies, remaining_jiffies;
#elif defined(__FreeBSD__)
    unsigned long long target_jiffies, tmp_jiffies, remaining_jiffies;
#endif
#ifdef DEBUG
printk("wait_remaining_ms_from_jiffies - begin (slow?) (%ld, %d)\n",
    timestamp_jiffies, to_wait_ms);
    unsigned long conversion_val = msecs_to_jiffies_timeout(to_wait_ms);
    printk("wait_remaining_ms_from_jiffies %ld ms are %llu jiffies\n",
        to_wait_ms, conversion_val);
#endif
    /*
     * Don't re-read the value of "jiffies" every time since it may change
     * behind our back and break the math.
     */
    tmp_jiffies = jiffies;
#ifdef DEBUG
if (tmp_jiffies < 0) {
    printk("wait_remaining_ms_from_jiffies - <0 must never happen!\n");
    tmp_jiffies = timestamp_jiffies;
}
#endif
    target_jiffies = timestamp_jiffies +
             msecs_to_jiffies_timeout(to_wait_ms);
#ifdef DEBUG
printk("wait_remaining_ms_from_jiffies - tmp_jiffies = %llu, target_jiffies = %llu\n",
    tmp_jiffies, target_jiffies);
#endif
    if (time_after(target_jiffies, tmp_jiffies)) {
#ifdef DEBUG
printk("wait_remaining_ms_from_jiffies - time_after\n");
#endif
        remaining_jiffies = target_jiffies - tmp_jiffies;
        while (remaining_jiffies) {
#ifdef DEBUG
printk("wait_remaining_ms_from_jiffies - remaining_jiffies=%llu; schedule_timeout_uninterruptible\n",
        remaining_jiffies);
if (remaining_jiffies > 1000) {
    printk("resetting remaining_jiffies to 1000\n");
    remaining_jiffies=1000;
}
#endif
            remaining_jiffies =
                schedule_timeout_uninterruptible(remaining_jiffies);
        }
    }
#ifdef DEBUG
printk("wait_remaining_ms_from_jiffies - end\n");
#endif
}

here's the output, I'm seeing:
Code: 
Dec 28 10:59:03 framework kernel: wait_remaining_ms_from_jiffies - begin (slow?) (0, 30)
Dec 28 10:59:03 framework kernel: wait_remaining_ms_from_jiffies 30 ms are 31 jiffies
Dec 28 10:59:03 framework kernel: wait_remaining_ms_from_jiffies - tmp_jiffies = -2146056371, target_jiffies = 31
Dec 28 10:59:03 framework kernel: wait_remaining_ms_from_jiffies - time_afterwait_remaining_ms_from_jiffies - remaining_jiffies=2146056402; schedule_timeout_uninterruptible

In theory, this should NEVER happen, but that's what I'm getting. So I expect I've got a mistake in my printf or linuxkpi's printf/printk is doing some unexpected magic? Problem is I-m then getting a calculated wait period that is so huge, that the whole kernel hangs, because of the "remaining_jiffies" value, that is calculated.

PS. Some of the debugs are not in the output, because I just put them in. I'm about to try them out and see what happens; including the "capping" at 1000 ticks.
 
Ok, this is solved from the moment. I recompiled everything and finally getting positive values. The ticks are still way out there and seem to be wrong, but that's a different issue.

Code: 
c 28 13:49:03 framework kernel: wait_remaining_ms_from_jiffies - begin (slow?) (0, 30)
Dec 28 13:49:03 framework kernel: wait_remaining_ms_from_jiffies 30 ms are 31 jiffies
Dec 28 13:49:03 framework kernel: wait_remaining_ms_from_jiffies - tmp_jiffies = 18446744071565303851, target_jiffies = 31
Dec 28 13:49:03 framework kernel: wait_remaining_ms_from_jiffies - time_after
Dec 28 13:49:03 framework kernel: wait_remaining_ms_from_jiffies - remaining_jiffies=2144247796; schedule_timeout_uninterruptible
Dec 28 13:49:03 framework kernel: resetting remaining_jiffies to 1000

Thanks for pushing me in the right direction!
 
You must log in or register to reply here.
Back
Top