DML sql execution time slow down PGv14 compared with PGv13

2022-12-15 Thread James Pang (chaolpan) 
Hi,
   We had some load test ( DML inserts/deletes/updates/ on tens of hash 
partition tables)  and found that PGV14 slow down 10-15% compared with PGV13.  
Same test server, same schema tables and data. From pg_stat_statements, sql 
exec_time, we did found similar mean_exec_time increased from 5%-25% with same 
SQL statements. Both v14 and v13 give very fast sql response time, just compare 
the %diff from sql statements mean_exec_time.
   Now, I get a pgbench test in same server, the steps as below, it's similar 
as our application workload test, small sql statement running very fast but did 
see v14 slow down 5-10% for DML,compared with v13.
   1.date;pgbench -i -s 6000 -F 85 -U pgbench --partition-method=hash 
--partitions=32
   2.reboot OS to refresh buffer
   3.run four rounds of test:  date;pgbench -c 10 -j 10 -n -T 180 -U pgbench -M 
prepared

Compare 14.6 and 13.9 on RHEL8.4,  the "add primary key" step 14.6 much fast 
than 13.9, but most of insert/updates slow down 5-10%.  The table is very 
simple and sql should be same, no idea what contribute to the sql exec_time 
difference?  Attached please find sql exec_time.

I copy the sql here too,

version
min_exec_time
max_exec_time
mean_exec_time
calls
SQL
13.9
0.002814
1.088559
0.004214798
3467468
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, 
$4, CURRENT_TIMESTAMP)
14.6
0.003169
0.955241
0.004482497
345
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, 
$4, CURRENT_TIMESTAMP)
%diff
12.61549396

6.351410351














13.9
0.013449
15.638027
1.18372356
3467468
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
14.6
0.016109
133.106913
1.228978518
345
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
%diff
19.77842219

3.823101875








13.9
0.005433
2.051736
0.008532748
3467468
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
14.6
0.00625
1.847688
0.009062454
345
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
%diff
15.03773238

6.207914363



Thanks,

James


sqlstats_v13_v14_pgbench.xlsx
Description: sqlstats_v13_v14_pgbench.xlsx

DML sql execution time slow down PGv14 compared with PGv13

2022-12-15 Thread James Pang (chaolpan) 
Hi,
   We had some load test ( DML inserts/deletes/updates)  and found that PGV14 
slow down 10-15% compared with PGV13.  Same test server, same schema tables and 
data. From pg_stat_statements, sql exec_time, we did found similar 
mean_exec_time increased from 20%-30% with same SQL statements. Both v14 and 
v13 give very fast sql response time, just compare the %diff from sql 
statements mean_exec_time.
   Now, I get a pgbench test in same server, the steps as below, small sql 
statement running very fast, not like our application load test that show 
INSERTS slow down 20-30%, but did see v14 slow down 5-10% for DML,compared with 
v13.
   1.date;pgbench -i -s 6000 -F 85 -U pgbench --partition-method=hash 
--partitions=32
   2.reboot OS to refresh buffer
   3.run four rounds of test:  date;pgbench -c 10 -j 10 -n -T 180 -U pgbench -M 
prepared

Compare 14.6 and 13.9 on RHEL8.4,  the "add primary key" step 14.6 much fast 
than 13.9, but most of insert/updates slow down 5-10%.  The table is very 
simple and sql should be same, no idea what contribute to the sql exec_time 
difference?  Attached please find sql exec_time.

I copy the sql here too,

version
min_exec_time
max_exec_time
mean_exec_time
calls
SQL
13.9
0.002814
1.088559
0.004214798
3467468
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, 
$4, CURRENT_TIMESTAMP)
14.6
0.003169
0.955241
0.004482497
345
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, 
$4, CURRENT_TIMESTAMP)
%diff
12.61549396

6.351410351














13.9
0.013449
15.638027
1.18372356
3467468
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
14.6
0.016109
133.106913
1.228978518
345
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
%diff
19.77842219

3.823101875








13.9
0.005433
2.051736
0.008532748
3467468
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
14.6
0.00625
1.847688
0.009062454
345
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
%diff
15.03773238

6.207914363



Thanks,

James


sqlstats_v13_v14_pgbench.xlsx
Description: sqlstats_v13_v14_pgbench.xlsx

Re: DML sql execution time slow down PGv14 compared with PGv13

2022-12-15 Thread Samed YILDIRIM 
Hello James,

Could you please add configurations of your PostgreSQL installations too?
I also wonder why you skip vacuuming (-n parameter) before starting of
tests.

Best regards.
Samed YILDIRIM


On Thu, 15 Dec 2022 at 10:22, James Pang (chaolpan) 
wrote:

> Hi,
>
>We had some load test ( DML inserts/deletes/updates)  and found that
> PGV14 slow down 10-15% compared with PGV13.  Same test server, same schema
> tables and data. From pg_stat_statements, sql exec_time, we did found
> similar mean_exec_time increased from 20%-30% with same SQL statements.
> Both v14 and v13 give very fast sql response time, just compare the %diff
> from sql statements mean_exec_time.
>
>Now, I get a pgbench test in same server, the steps as below, small sql
> statement running very fast, not like our application load test that show
> INSERTS slow down 20-30%, but did see v14 slow down 5-10% for DML,compared
> with v13.
>
>1.date;pgbench -i -s 6000 -F 85 -U pgbench --partition-method=hash
> --partitions=32
>
>2.reboot OS to refresh buffer
>
>3.run four rounds of test:  date;pgbench -c 10 -j 10 -n -T 180 -U
> pgbench -M prepared
>
>
>
> Compare 14.6 and 13.9 on RHEL8.4,  the “add primary key” step 14.6 much
> fast than 13.9, but most of insert/updates slow down 5-10%.  The table is
> very simple and sql should be same, no idea what contribute to the sql
> exec_time difference?  Attached please find sql exec_time.
>
>
>
> I copy the sql here too,
>
>
>
> version
>
> min_exec_time
>
> max_exec_time
>
> mean_exec_time
>
> calls
>
> SQL
>
> 13.9
>
> 0.002814
>
> 1.088559
>
> 0.004214798
>
> 3467468
>
> INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2,
> $3, $4, CURRENT_TIMESTAMP)
>
> 14.6
>
> 0.003169
>
> 0.955241
>
> 0.004482497
>
> 345
>
> INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2,
> $3, $4, CURRENT_TIMESTAMP)
>
> %diff
>
> 12.61549396
>
>
>
> 6.351410351
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> 13.9
>
> 0.013449
>
> 15.638027
>
> 1.18372356
>
> 3467468
>
> UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
>
> 14.6
>
> 0.016109
>
> 133.106913
>
> 1.228978518
>
> 345
>
> UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
>
> %diff
>
> 19.77842219
>
>
>
> 3.823101875
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
> 13.9
>
> 0.005433
>
> 2.051736
>
> 0.008532748
>
> 3467468
>
> UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
>
> 14.6
>
> 0.00625
>
> 1.847688
>
> 0.009062454
>
> 345
>
> UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
>
> %diff
>
> 15.03773238
>
>
>
> 6.207914363
>
>
>
>
>
>
>
> Thanks,
>
>
>
> James
>

RE: DML sql execution time slow down PGv14 compared with PGv13

2022-12-15 Thread James Pang (chaolpan) 
When pgbench -i , it did already done vacuuming just before pgbench tpc-b test, 
below is the output of init loading.  Same postgresql.conf for both v14 and 
v13, please check attached.

date;pgbench -i -s 6000 -F 85 -U pgbench --partitions 6
Fri Dec  9 05:54:17 GMT 2022
dropping old tables...
creating tables...
creating 6 partitions...
generating data (client-side)...
6 of 6 tuples (100%) done (elapsed 577.18 s, remaining 0.00 s))
vacuuming...
creating primary keys...
done in 1568.52 s (drop tables 8.40 s, create tables 0.02 s, client-side 
generate 579.66 s, vacuum 339.54 s, primary keys 640.91 s).

Thanks,

James

From: Samed YILDIRIM 
Sent: Thursday, December 15, 2022 4:38 PM
To: James Pang (chaolpan) 
Cc: [email protected]
Subject: Re: DML sql execution time slow down PGv14 compared with PGv13

Hello James,

Could you please add configurations of your PostgreSQL installations too?
I also wonder why you skip vacuuming (-n parameter) before starting of tests.

Best regards.
Samed YILDIRIM


On Thu, 15 Dec 2022 at 10:22, James Pang (chaolpan) 
mailto:[email protected]>> wrote:
Hi,
   We had some load test ( DML inserts/deletes/updates)  and found that PGV14 
slow down 10-15% compared with PGV13.  Same test server, same schema tables and 
data. From pg_stat_statements, sql exec_time, we did found similar 
mean_exec_time increased from 20%-30% with same SQL statements. Both v14 and 
v13 give very fast sql response time, just compare the %diff from sql 
statements mean_exec_time.
   Now, I get a pgbench test in same server, the steps as below, small sql 
statement running very fast, not like our application load test that show 
INSERTS slow down 20-30%, but did see v14 slow down 5-10% for DML,compared with 
v13.
   1.date;pgbench -i -s 6000 -F 85 -U pgbench --partition-method=hash 
--partitions=32
   2.reboot OS to refresh buffer
   3.run four rounds of test:  date;pgbench -c 10 -j 10 -n -T 180 -U pgbench -M 
prepared

Compare 14.6 and 13.9 on RHEL8.4,  the “add primary key” step 14.6 much fast 
than 13.9, but most of insert/updates slow down 5-10%.  The table is very 
simple and sql should be same, no idea what contribute to the sql exec_time 
difference?  Attached please find sql exec_time.

I copy the sql here too,

version
min_exec_time
max_exec_time
mean_exec_time
calls
SQL
13.9
0.002814
1.088559
0.004214798
3467468
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, 
$4, CURRENT_TIMESTAMP)
14.6
0.003169
0.955241
0.004482497
345
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, 
$4, CURRENT_TIMESTAMP)
%diff
12.61549396

6.351410351














13.9
0.013449
15.638027
1.18372356
3467468
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
14.6
0.016109
133.106913
1.228978518
345
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
%diff
19.77842219

3.823101875








13.9
0.005433
2.051736
0.008532748
3467468
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
14.6
0.00625
1.847688
0.009062454
345
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
%diff
15.03773238

6.207914363



Thanks,

James


postgresql.conf
Description: postgresql.conf

RE: DML sql execution time slow down PGv14 compared with PGv13

2022-12-15 Thread James Pang (chaolpan) 
Actually, with our application that’s JDBC clients instead of pgbench , we saw 
similar DML exec_time increase too.

From: James Pang (chaolpan) 
Sent: Thursday, December 15, 2022 4:45 PM
To: Samed YILDIRIM 
Cc: [email protected]
Subject: RE: DML sql execution time slow down PGv14 compared with PGv13

When pgbench -i , it did already done vacuuming just before pgbench tpc-b test, 
below is the output of init loading.  Same postgresql.conf for both v14 and 
v13, please check attached.

date;pgbench -i -s 6000 -F 85 -U pgbench --partitions 6
Fri Dec  9 05:54:17 GMT 2022
dropping old tables...
creating tables...
creating 6 partitions...
generating data (client-side)...
6 of 6 tuples (100%) done (elapsed 577.18 s, remaining 0.00 s))
vacuuming...
creating primary keys...
done in 1568.52 s (drop tables 8.40 s, create tables 0.02 s, client-side 
generate 579.66 s, vacuum 339.54 s, primary keys 640.91 s).

Thanks,

James

From: Samed YILDIRIM mailto:[email protected]>>
Sent: Thursday, December 15, 2022 4:38 PM
To: James Pang (chaolpan) mailto:[email protected]>>
Cc: 
[email protected]
Subject: Re: DML sql execution time slow down PGv14 compared with PGv13

Hello James,

Could you please add configurations of your PostgreSQL installations too?
I also wonder why you skip vacuuming (-n parameter) before starting of tests.

Best regards.
Samed YILDIRIM


On Thu, 15 Dec 2022 at 10:22, James Pang (chaolpan) 
mailto:[email protected]>> wrote:
Hi,
   We had some load test ( DML inserts/deletes/updates)  and found that PGV14 
slow down 10-15% compared with PGV13.  Same test server, same schema tables and 
data. From pg_stat_statements, sql exec_time, we did found similar 
mean_exec_time increased from 20%-30% with same SQL statements. Both v14 and 
v13 give very fast sql response time, just compare the %diff from sql 
statements mean_exec_time.
   Now, I get a pgbench test in same server, the steps as below, small sql 
statement running very fast, not like our application load test that show 
INSERTS slow down 20-30%, but did see v14 slow down 5-10% for DML,compared with 
v13.
   1.date;pgbench -i -s 6000 -F 85 -U pgbench --partition-method=hash 
--partitions=32
   2.reboot OS to refresh buffer
   3.run four rounds of test:  date;pgbench -c 10 -j 10 -n -T 180 -U pgbench -M 
prepared

Compare 14.6 and 13.9 on RHEL8.4,  the “add primary key” step 14.6 much fast 
than 13.9, but most of insert/updates slow down 5-10%.  The table is very 
simple and sql should be same, no idea what contribute to the sql exec_time 
difference?  Attached please find sql exec_time.

I copy the sql here too,

version
min_exec_time
max_exec_time
mean_exec_time
calls
SQL
13.9
0.002814
1.088559
0.004214798
3467468
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, 
$4, CURRENT_TIMESTAMP)
14.6
0.003169
0.955241
0.004482497
345
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, 
$4, CURRENT_TIMESTAMP)
%diff
12.61549396

6.351410351














13.9
0.013449
15.638027
1.18372356
3467468
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
14.6
0.016109
133.106913
1.228978518
345
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2
%diff
19.77842219

3.823101875








13.9
0.005433
2.051736
0.008532748
3467468
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
14.6
0.00625
1.847688
0.009062454
345
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2
%diff
15.03773238

6.207914363



Thanks,

James

Re: DML sql execution time slow down PGv14 compared with PGv13

2022-12-15 Thread David Rowley 
On Thu, 15 Dec 2022 at 21:12, James Pang (chaolpan)  wrote:
>We had some load test ( DML inserts/deletes/updates/ on tens of hash 
> partition tables)  and found that PGV14 slow down 10-15% compared with PGV13. 
>  Same test server, same schema tables and data. From pg_stat_statements, sql 
> exec_time, we did found similar mean_exec_time increased from 5%-25% with 
> same SQL statements. Both v14 and v13 give very fast sql response time, just 
> compare the %diff from sql statements mean_exec_time.

I tried this out on the tip of the PG13 and PG14 branch with the same
scale of pgbench as you mentioned and I don't see the same slowdown as
you do.

PG13:
tps = 1711.980109 (excluding connections establishing)

PG14:
tps = 1736.466835 (without initial connection time)

As for why yours might be slower.  You might want to have a look at
the EXPLAIN ANALYZE output for the UPDATE statements. You can recreate
the -M prepared by using PREPARE and EXECUTE. You might want to
execute the statements 6 times and see if the plan changes on the 6th
execution.  It's likely not impossible that PG14 is using custom
plans, whereas PG13 might be using generic plans for these updates.
There were some quite significant changes made to the query planner in
PG14 that changed how planning works for UPDATEs and DELETEs from
partitioned tables.  Perhaps there's some reason there that the
custom/generic plan choice might differ. I see no reason why INSERT
would have become slower. Both the query planning and execution is
very different for INSERT.

You might also want to have a look at what perf says. If you have the
debug symbols installed, then you could just watch "perf top --pid=". Maybe that will show you
something interesting.

RE: DML sql execution time slow down PGv14 compared with PGv13

2022-12-15 Thread James Pang (chaolpan) 
Did you check pg_stat_statements ? looks like select some better , but DML 
decreased.



-Original Message-
From: David Rowley  
Sent: Thursday, December 15, 2022 6:42 PM
To: James Pang (chaolpan) 
Cc: [email protected]
Subject: Re: DML sql execution time slow down PGv14 compared with PGv13

On Thu, 15 Dec 2022 at 21:12, James Pang (chaolpan)  wrote:
>We had some load test ( DML inserts/deletes/updates/ on tens of hash 
> partition tables)  and found that PGV14 slow down 10-15% compared with PGV13. 
>  Same test server, same schema tables and data. From pg_stat_statements, sql 
> exec_time, we did found similar mean_exec_time increased from 5%-25% with 
> same SQL statements. Both v14 and v13 give very fast sql response time, just 
> compare the %diff from sql statements mean_exec_time.

I tried this out on the tip of the PG13 and PG14 branch with the same scale of 
pgbench as you mentioned and I don't see the same slowdown as you do.

PG13:
tps = 1711.980109 (excluding connections establishing)

PG14:
tps = 1736.466835 (without initial connection time)

As for why yours might be slower.  You might want to have a look at the EXPLAIN 
ANALYZE output for the UPDATE statements. You can recreate the -M prepared by 
using PREPARE and EXECUTE. You might want to execute the statements 6 times and 
see if the plan changes on the 6th execution.  It's likely not impossible that 
PG14 is using custom plans, whereas PG13 might be using generic plans for these 
updates.
There were some quite significant changes made to the query planner in
PG14 that changed how planning works for UPDATEs and DELETEs from partitioned 
tables.  Perhaps there's some reason there that the custom/generic plan choice 
might differ. I see no reason why INSERT would have become slower. Both the 
query planning and execution is very different for INSERT.

You might also want to have a look at what perf says. If you have the debug 
symbols installed, then you could just watch "perf top --pid=". Maybe that will show you something interesting.

time sorted UUIDs

2022-12-15 Thread Tim Jones 
Hi, 

could someone please comment on this article 
https://vladmihalcea.com/uuid-database-primary-key/ specifically re the 
comments (copied below) in regards to a Postgres database. 

... 


But, using a random UUID as a database table Primary Key is a bad idea for 
multiple reasons. 

First, the UUID is huge. Every single record will need 16 bytes for the 
database identifier, and this impacts all associated Foreign Key columns as 
well. 

Second, the Primary Key column usually has an associated B+Tree index to speed 
up lookups or joins, and B+Tree indexes store data in sorted order. 

However, indexing random values using B+Tree causes a lot of problems: 

* Index pages will have a very low fill factor because the values come 
randomly. So, a page of 8kB will end up storing just a few elements, therefore 
wasting a lot of space, both on the disk and in the database memory, as index 
pages could be cached in the Buffer Pool. 
* Because the B+Tree index needs to rebalance itself in order to maintain 
its equidistant tree structure, the random key values will cause more index 
page splits and merges as there is no pre-determined order of filling the tree 
structure. 
... 


Any other general comments about time sorted UUIDs would be welcome. 



Thanks, 

Tim Jones

Re: time sorted UUIDs

2022-12-15 Thread Laurenz Albe 
On Thu, 2022-12-15 at 10:56 +1300, Tim Jones wrote:
> could someone please comment on this article 
> https://vladmihalcea.com/uuid-database-primary-key/
> specifically re the comments (copied below) in regards to a Postgres database.
> 
> ...
> But, using a random UUID as a database table Primary Key is a bad idea for 
> multiple reasons.
> First, the UUID is huge. Every single record will need 16 bytes for the 
> database identifier,
> and this impacts all associated Foreign Key columns as well.
> Second, the Primary Key column usually has an associated B+Tree index to 
> speed up lookups or
> joins, and B+Tree indexes store data in sorted order.
> However, indexing random values using B+Tree causes a lot of problems:
>  * Index pages will have a very low fill factor because the values come 
> randomly. So, a page
>of 8kB will end up storing just a few elements, therefore wasting a lot of 
> space, both
>on the disk and in the database memory, as index pages could be cached in 
> the Buffer Pool.
>  * Because the B+Tree index needs to rebalance itself in order to maintain 
> its equidistant
>tree structure, the random key values will cause more index page splits 
> and merges as
>there is no pre-determined order of filling the tree structure.

I'd say that is quite accurate.

Yours,
Laurenz Albe

Re: time sorted UUIDs

2022-12-15 Thread Adrien Nayrat 

Tomas Vondra made an extension to have sequential uuid:

https://www.2ndquadrant.com/en/blog/sequential-uuid-generators/
https://github.com/tvondra/sequential-uuids


--
Adrien NAYRAT

RE: DML sql execution time slow down PGv14 compared with PGv13

2022-12-15 Thread James Pang (chaolpan) 
Did you check pg_stat_statements ? looks like select better, but DML decreased, 
so average tps looks similar .



-Original Message-
From: David Rowley  
Sent: Thursday, December 15, 2022 6:42 PM
To: James Pang (chaolpan) 
Cc: [email protected]
Subject: Re: DML sql execution time slow down PGv14 compared with PGv13

On Thu, 15 Dec 2022 at 21:12, James Pang (chaolpan)  wrote:
>We had some load test ( DML inserts/deletes/updates/ on tens of hash 
> partition tables)  and found that PGV14 slow down 10-15% compared with PGV13. 
>  Same test server, same schema tables and data. From pg_stat_statements, sql 
> exec_time, we did found similar mean_exec_time increased from 5%-25% with 
> same SQL statements. Both v14 and v13 give very fast sql response time, just 
> compare the %diff from sql statements mean_exec_time.

I tried this out on the tip of the PG13 and PG14 branch with the same scale of 
pgbench as you mentioned and I don't see the same slowdown as you do.

PG13:
tps = 1711.980109 (excluding connections establishing)

PG14:
tps = 1736.466835 (without initial connection time)

As for why yours might be slower.  You might want to have a look at the EXPLAIN 
ANALYZE output for the UPDATE statements. You can recreate the -M prepared by 
using PREPARE and EXECUTE. You might want to execute the statements 6 times and 
see if the plan changes on the 6th execution.  It's likely not impossible that 
PG14 is using custom plans, whereas PG13 might be using generic plans for these 
updates.
There were some quite significant changes made to the query planner in
PG14 that changed how planning works for UPDATEs and DELETEs from partitioned 
tables.  Perhaps there's some reason there that the custom/generic plan choice 
might differ. I see no reason why INSERT would have become slower. Both the 
query planning and execution is very different for INSERT.

You might also want to have a look at what perf says. If you have the debug 
symbols installed, then you could just watch "perf top --pid=". Maybe that will show you something interesting.