unexcpected output

[nominalval]

Hello.

After testing this :

#include <stdio.h>
#include <pthread.h>
#include <stdint.h>
#include "thpool.h"
#include <time.h>

void task(void *arg){
	printf("Thread #%u working on %d\n", (int)pthread_self(), (int) arg);
	usleep(rand()%1000000+1000000); // intensive task
	printf("Thread #%u finished on %d\n", (int)pthread_self(), (int) arg);
}


int main(){
	printf("Starting program v1 ...\n");
	sleep(1);
	
	srand(time(NULL));
	puts("Making threadpool with 20 threads");
	threadpool thpool = thpool_init(20);

	puts("Adding 9999 tasks to threadpool");
	int i;
	for (i=0; i<9999; i++)
	{
		thpool_add_work(thpool, task, (void*)(uintptr_t)i);
	};

	thpool_wait(thpool);
	puts("Killing threadpool");
	thpool_destroy(thpool);
	
	return 0;
}

I saw the following output:

Thread #3019622144 working on 7865
Thread #2918909696 finished on 7845
Thread #2918909696 working on 7866
Thread #2876946176 finished on 7846
Thread #2876946176 working on 7867
Thread #3011229440 finished on 7852
Thread #3011229440 working on 7868
Thread #2944087808 finished on 7848
Thread #2944087808 working on 7869
Thread #2935695104 finished on 7856
Thread #2935695104 working on 7870
Thread #2902124288 finished on 7861
Thread #2902124288 working on 7871
Thread #3028014848 finished on 7858
Thread #3028014848 working on 7872
Thread #3002836736 finished on 7855
Thread #3002836736 working on 7873
Thread #2977658624 finished on 7851
Thread #2977658624 working on 7874
Thread #2952480512 finished on 7864
Thread #2952480512 working on 7875
Thread #2986051328 finished on 7849
Thread #2986051328 working on 7876
Thread #2969265920 finished on 7860
Thread #2969265920 working on 7877

Shouldn't be something like this :

Thread #2944087808 finished on 7848
Thread #2944087808 working on 7869
Thread #2918909696 working on 7866
Thread #2876946176 working on 7867
Thread #3028014848 working on 7872
Thread #2952480512 working on 7875
Thread #2935695104 working on 7870
Thread #3028014848 finished on 7858
Thread #2986051328 working on 7876
Thread #2977658624 finished on 7851
Thread #2935695104 finished on 7856
Thread #2952480512 finished on 7864
Thread #2977658624 working on 7874
Thread #3002836736 working on 7873
Thread #2918909696 finished on 7845
Thread #3011229440 working on 7868
Thread #2969265920 working on 7877
Thread #3011229440 finished on 7852
Thread #3019622144 working on 7865
Thread #2986051328 finished on 7849

I have a feeling that this program is executing them one task after another and not in parallel.

I basically want to run some time intensive tasks (most of the time i am waiting for network response) in parallel in this way:

int i;
for (;;)
{
    thpool_add_work(thpool, task, (void*)(uintptr_t)i);
};

I don't care about getting back any response for any of the tasks submitted.

Thank you for answer.

[swofford]

(Trying to help the maintainers clear out some issues...)

Why do you think your output is unexpected? Your sleep times are between 1 and 2 seconds, so (usually) the next thing that will happen after a task returns is a new task starting on the same thread that just completed its previous task. This is exactly what your output shows.

To see it more clearly, replace your task function with the following:

#include <sys/time.h>

double startTime;
double wallTime(void) {
    struct timeval tv;
    gettimeofday(&tv,NULL);
    return tv.tv_sec + tv.tv_usec/1e6 - startTime;
}

void task(void *arg){
	int sleep_time = rand()%1000000+1000000;
	printf("%5.2f: Thread #%p working on %3ld (%.2f)\n",
	       wallTime(), (void *)pthread_self(), (intptr_t)arg, sleep_time/1e6);
	usleep(sleep_time); // intensive task
	printf("%5.2f: Thread #%p finished on %2ld (%.2f)\n",
	       wallTime(), (void *)pthread_self(), (intptr_t)arg, sleep_time/1e6);
}

Everything is completely hunky dory:

 0.00: Thread #0x700001bd6000 working on   0 (1.87)    <-- 1.87 sec task starts on thread 0x700001bd6000
 0.00: Thread #0x7000018c4000 working on   2 (1.59)
 0.00: Thread #0x700001c59000 working on   3 (1.64)
 0.00: Thread #0x700001a4d000 working on   1 (1.26)
 0.00: Thread #0x700002177000 working on   6 (1.53)
 0.00: Thread #0x700001cdc000 working on   4 (1.74)
 0.00: Thread #0x7000019ca000 working on   8 (1.03)
 0.00: Thread #0x700001d5f000 working on  10 (1.63)
 0.00: Thread #0x700001b53000 working on   9 (1.97)
 0.00: Thread #0x700001ad0000 working on   7 (1.32)
                  .
                  .
                  .
 1.64: Thread #0x700001c59000 working on  34 (1.26)
 1.75: Thread #0x700001cdc000 finished on  4 (1.74)
 1.75: Thread #0x700001cdc000 working on  35 (1.83)
 1.78: Thread #0x7000020f4000 finished on 11 (1.78)
 1.78: Thread #0x7000020f4000 working on  36 (1.67)
 1.86: Thread #0x700001f6b000 finished on 17 (1.86)
 1.86: Thread #0x700001f6b000 working on  37 (1.64)
 1.87: Thread #0x700001bd6000 finished on  0 (1.87)    <-- 1.87 sec task finishes on thread 0x700001bd6000
 1.87: Thread #`0x700001bd6000 working on  38 (1.81)   <-- new (1.81 sec) task starts immediately on this thread
                  .
                  .
                  .
 3.58: Thread #0x700001cdc000 working on  58 (1.91)
 3.67: Thread #0x700001947000 finished on 41 (1.41)
 3.67: Thread #0x700001947000 working on  59 (1.70)
 3.68: Thread #0x700001bd6000 finished on 38 (1.81)    <-- 1.81 sec task finishes at 1.87+1.81 = 3.68 elapsed seconds
 3.68: Thread #0x700001bd6000 working on  60 (1.20)
 3.88: Thread #0x700001e65000 finished on 43 (1.20)
 3.88: Thread #0x700001e65000 working on  61 (1.30)