Impressive numbers. Thanks.
Milen Dyankov wrote:
Hi all,
In my "CompanyBean" (CMP) I have field of type String named "symbol" which is primary key.
I also have finder "findAll" with EJB-QL query "SELECT OBJECT(c) FROM Company c".
In "CompanyManagerBean" (SLSB) there is method "findAll" which contains code :
[ -=- snip -=- ]
log.debug(" +-+-+-+-+- JUST BEFORE getCompanyLocalHome() -+-+-+-+-+"); CompanyLocalHome companyLocalHome = IntaktHelper.getCompanyLocalHome();
log.debug(" +-+-+-+-+- JUST BEFORE findAll() -+-+-+-+-+"); Iterator iterator = companyLocalHome.findAll().iterator(); log.debug(" +-+-+-+-+- JUST AFTER findAll() -+-+-+-+-+");
ArrayList symbols = new ArrayList();
while(iterator.hasNext()) { symbols.add((String)((CompanyLocal)iterator.next()).getSymbol()); }
[ -=- snip -=- ]
There are 5000 companies in the database and this takes about over 15 seconds.
This is what I have in JBoss Log:
[ -=- snip -=- ]
2003-11-13 14:08:36,552 DEBUG [laser.ejb.intakt.IntaktBean ] (Thread-49:getCompaniesList) called
2003-11-13 14:08:36,552 DEBUG [laser.ejb.intakt.IntaktBean ] (Thread-49:getCompaniesList) ticketId :d52d83850a00016c0001d48c43e7176f
2003-11-13 14:08:36,552 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-49:getCompaniesList findCompanies) called
[ -=- snip -=- ]
2003-11-13 14:08:36,581 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-49:getCompaniesList findCompanies) +-+-+-+-+- JUST BEFORE getCompanyLocalHome() -+-+-+-+-+
2003-11-13 14:08:36,581 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-49:getCompaniesList findCompanies) +-+-+-+-+- JUST BEFORE findAll() -+-+-+-+-+
2003-11-13 14:08:36,582 DEBUG [laser.ejb.intakt.CompanyBean ] (Thread-49:getCompaniesList findCompanies setEntityContext) called
2003-11-13 14:08:36,582 DEBUG [laser.ejb.pacs.TicketBean ] (Thread-49:getCompaniesList findCompanies) *** stored!
2003-11-13 14:08:36,582 DEBUG [cmp.jdbc.JDBCStoreEntityCommand.Ticket ] (Thread-49:getCompaniesList findCompanies) Executing SQL: UPDATE Ticket SET expires=? WHERE id=?
2003-11-13 14:08:36,584 DEBUG [cmp.jdbc.JDBCStoreEntityCommand.Ticket ] (Thread-49:getCompaniesList findCompanies) Rows affected = 1
*** 2003-11-13 14:08:36,585 DEBUG [jdbc.JDBCEJBQLQuery.Company.findAll ] (Thread-49:getCompaniesList findCompanies) Executing SQL: SELECT t0_c.symbol FROM Company t0_c
*** 2003-11-13 14:08:48,343 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-49:getCompaniesList findCompanies) +-+-+-+-+- JUST AFTER findAll() -+-+-+-+-+
2003-11-13 14:08:50,630 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-49:getCompaniesList findCompanies) end
2003-11-13 14:08:50,631 DEBUG [laser.ejb.intakt.IntaktBean ] (Thread-49:getCompaniesList) end
2003-11-13 14:08:50,631 DEBUG [laser.ejb.intakt.CompanyBean ] (Thread-49:ejbStore) called
2003-11-13 14:08:50,631 DEBUG [laser.ejb.intakt.CompanyBean ] (Thread-49:ejbStore) called
2003-11-13 14:08:50,631 DEBUG [laser.ejb.intakt.CompanyBean ] (Thread-49:ejbStore) called
2003-11-13 14:08:50,631 DEBUG [laser.ejb.intakt.CompanyBean ] (Thread-49:ejbStore) called
2003-11-13 14:08:50,631 DEBUG [laser.ejb.intakt.CompanyBean ] (Thread-49:ejbStore) called
.....
[laser.ejb.intakt.CompanyBean ] (Thread-49:ejbStore) CALLED 4995 more times
.....
According to the logs "findAll" method takes little less then 12 seconds.
In the beginning I thought that there was new query to get the symbol from the database.
But here is what mySQL log shows:
[ -=- snip -=- ] 031113 14:08:36 9 Query SET autocommit=0 9 Query SELECT t0_c.symbol FROM Company t0_c 031113 14:08:52 9 Query commit 9 Query SET autocommit=1 [ -=- snip -=- ]
Now changing my code from :
symbols.add((String)((CompanyLocal)iterator.next()).getSymbol()); to: symbols.add((String)((CompanyLocal)iterator.next()).getPrimaryKey());
results is much better performance:
2003-11-13 14:27:16,098 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-46:getCompaniesList findCompanies) called
[ -=- snip -=- ]
2003-11-13 14:27:16,112 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-46:getCompaniesList findCompanies) +-+-+-+-+- JUST BEFORE getCompanyLocalHome() -+-+-+-+-+
2003-11-13 14:27:16,112 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-46:getCompaniesList findCompanies) +-+-+-+-+- JUST BEFORE findAll() -+-+-+-+-+
2003-11-13 14:27:16,112 DEBUG [laser.ejb.intakt.CompanyBean ] (Thread-46:getCompaniesList findCompanies setEntityContext) called
2003-11-13 14:27:16,112 DEBUG [laser.ejb.pacs.TicketBean ] (Thread-46:getCompaniesList findCompanies) *** stored!
2003-11-13 14:27:16,113 DEBUG [cmp.jdbc.JDBCStoreEntityCommand.Ticket ] (Thread-46:getCompaniesList findCompanies) Executing SQL: UPDATE Ticket SET expires=? WHERE id=?
2003-11-13 14:27:16,114 DEBUG [cmp.jdbc.JDBCStoreEntityCommand.Ticket ] (Thread-46:getCompaniesList findCompanies) Rows affected = 1
*** 2003-11-13 14:27:16,115 DEBUG [jdbc.JDBCEJBQLQuery.Company.findAll ] (Thread-46:getCompaniesList findCompanies) Executing SQL: SELECT t0_c.symbol FROM Company t0_c
*** 2003-11-13 14:27:18,564 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-46:getCompaniesList findCompanies) +-+-+-+-+- JUST AFTER findAll() -+-+-+-+-+
2003-11-13 14:27:18,564 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-46:getCompaniesList findCompanies) iterate and -- getPrimaryKey() -- and create VO!
2003-11-13 14:27:18,576 DEBUG [laser.ejb.intakt.CompanyManagerBean ] (Thread-46:getCompaniesList findCompanies) end
2003-11-13 14:27:18,577 DEBUG [laser.ejb.intakt.IntaktBean ] (Thread-46:getCompaniesList) end
[laser.ejb.intakt.CompanyBean ] (Thread-49:ejbStore) IS NOT CALLED AT ALL
As the log shows "jdbc.JDBCEJBQLQuery.Company.findAll" method takes now little over 2 seconds.
But it still loads the same data from the database:
[ -=- snip -=- ] 031113 14:27:16 13 Query SET autocommit=0 13 Query SELECT t0_c.symbol FROM Company t0_c 031113 14:27:18 13 Query commit 13 Query SET autocommit=1 [ -=- snip -=- ]
My configuration is: JBoss 3.2.1 | Sun J2SDK 1.4.1_02-b06 | Linux 2.4.22
I have set <commit-option>A</commit-option>.
I'm curious why it takes so long for doing 5000 times "getSymbol()" when there are no additional DB requests made?
Is this because of calling "ejbStore()"?
In another posting someone explained that "ejbStore()" is always called even if no synchronization is made
because the specs say so. But is it possible that calling 5000 times a method that basically does nothing,
causes such a performance loss?
Regards, Milen Dyankov
------------------------------------------------------- This SF.Net email sponsored by: ApacheCon 2003, 16-19 November in Las Vegas. Learn firsthand the latest developments in Apache, PHP, Perl, XML, Java, MySQL, WebDAV, and more! http://www.apachecon.com/ _______________________________________________ JBoss-user mailing list [EMAIL PROTECTED] https://lists.sourceforge.net/lists/listinfo/jboss-user
------------------------------------------------------- This SF.Net email sponsored by: ApacheCon 2003, 16-19 November in Las Vegas. Learn firsthand the latest developments in Apache, PHP, Perl, XML, Java, MySQL, WebDAV, and more! http://www.apachecon.com/ _______________________________________________ JBoss-user mailing list [EMAIL PROTECTED] https://lists.sourceforge.net/lists/listinfo/jboss-user
