semaphore access speed - Page 3

otheus · #15 (**permalink**) 09-20-2008

Quote:

Originally Posted by jim mcnamara

PS call utimes(struct tms *) to actual times, plus granularity is CLK_TCK, usually way better than time().

gettimeofday can be used to get wall time even more accurately as well. utimes() returns clock_t wall time.

Jim, utimes() doesn't do what you think it does. Gettimeofday is more correct, but then the code is a bit more complicated. Microsecond differences would not produce the disparities in performance he is seeing.

otheus · #16 (**permalink**) 09-20-2008

Quote:

Originally Posted by migurus

Jim,
I never tried profiling before, so I ran into some problem here:
$ gcc -pg -o tstloop tstloop.c
$ tstloop
128205.13 semop/s [0,0]
$ gprof tstloop
gprof: gmon.out file is missing call-graph data

That's strange. Any chance you're running a different program that's elsewhere in the path? Try for instance running "./tstloop".

Also, for gprof, use the -l option (small L). I get:

Code:

$ gprof -l  ./semget
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  Ts/call  Ts/call  name
 57.10      0.13     0.13                             main (semget.c:21 @ 80485f0)
 25.12      0.18     0.06                             main (semget.c:18 @ 804861f)
  9.14      0.20     0.02                             main (semget.c:17 @ 8048614)
  6.85      0.22     0.02                             main (semget.c:16 @ 80485e4)

Line 21 is the semctl() function. Line 18 is the semget() call.

Now that we have concrete results, I'd cross-post this on the Linuxquestions.org com site.

The next step would be to use the debug/profiling version of libc (which I don't have floating around) and see if we can use gprof to find the bottleneck therein. Or, look at the source. It would seem to be of great benefit to have this improved.

otheus · #17 (**permalink**) 09-20-2008

We can marginally rule out page-faults and the like by looking at the output from /usr/bin/time -v. The minor page fault means the OS reserved a page of memory, and that internal tables were modified, but the process wasn't suspended due to IO or anything like that. It turns out, all of these are due to either the profiling code or the program invocation.

Code:

$ /usr/bin/time -vv  ./semget
555555.56 semop/s [0,0]
Command exited with non-zero status 24
        Command being timed: "./semget"
        User time (seconds): 2.85
        System time (seconds): 6.12
        Percent of CPU this job got: 99%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:08.99
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 0
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 135
        Voluntary context switches: 7
        Involuntary context switches: 53
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 24

migurus · #18 (**permalink**) 09-22-2008

Quote:

Originally Posted by otheus

That's strange. Any chance you're running a different program that's elsewhere in the path? Try for instance running "./tstloop".

Also, for gprof, use the -l option (small L). I get:

.

to Jim:

tstloop is the only program, I did re-run
$ ./tstloop
$ gprof -l ./tstloop
gprof: gmon.out file is missing call-graph data

Thank you for taking it to other forum.

to Otheus:

tstloop compiled with profiling:

Code:

 
$ /usr/bin/time -vv ./tstloop
125000.00 semop/s [0,0]
Command exited with non-zero status 24
        Command being timed: "tstloop"
        User time (seconds): 15.05
        System time (seconds): 24.33
        Percent of CPU this job got: 99%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:39.39
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 0
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 121
        Voluntary context switches: 1
        Involuntary context switches: 326
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 24

and here are results from program compiled without profiling

Code:

 
$ /usr/bin/time -vv ./tstloop
128205.13 semop/s [0,0]
Command exited with non-zero status 24
        Command being timed: "./tstloop"
        User time (seconds): 15.39
        System time (seconds): 23.19
        Percent of CPU this job got: 99%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:38.59
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 0
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 0
        Minor (reclaiming a frame) page faults: 101
        Voluntary context switches: 1
        Involuntary context switches: 112
        Swaps: 0
        File system inputs: 0
        File system outputs: 0
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 24

otheus · #19 (**permalink**) 09-22-2008

Try running gprof with -p and -l . My newer version might not need the -p.

migurus · #20 (**permalink**) 09-22-2008

-p flag helped, please see results below

$ gprof -p ./tstloop
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
99.70 3.64 3.64 main

otheus · #21 (**permalink**) 09-23-2008

AND the -l flag.

More UNIX and Linux Forum Topics You Might Find Helpful
Thread	Thread Starter	Forum	Replies	Last Post
semaphore	raguramtgr	UNIX for Dummies Questions & Answers	7	06-15-2009 09:39 AM
Semaphore	Jaken	Shell Programming and Scripting	2	04-04-2009 05:10 PM
dmidecode, RAM speed = "Current Speed: Unknown"	Santi	Filesystems, Disks and Memory	0	02-16-2006 06:16 AM
Semaphore	vjsony	UNIX for Dummies Questions & Answers	3	04-07-2003 02:06 PM
semaphore	yls177	UNIX for Dummies Questions & Answers	1	10-08-2002 11:18 PM

Thread Tools	Search this Thread
Show Printable Version Email this Page	Search this Thread: Advanced Search
Display Modes	Rate This Thread
Linear Mode Switch to Hybrid Mode Switch to Threaded Mode	Rate This Thread: