This is not a new problem, but adding a publication to a bibliography with the [+] button fails >50% of the time with a “An error occured while processing your request” [sic] AJAX error. Right now I have 5 tabs open with publications that I want to add, and I have to babysit them checking back if they accept the [+]. After a couple of tries, I only succeeded for one of them. Even doing it in only one tab sometimes fails a number of times in a row.

Submitted by Lennart Kats on 20 March 2011 at 12:57

Come to think of it, actually maybe this did get worse. Lately I don’t think retrying the [+] button helps anymore. It either adds it, or it will keep refusing to add it.

Yes, this is extremely annoying. Haven’t figured out what is causing this.

Could it be related to the size of a bibliography? It seems simply cannot add papers anymore to the “spoofax-testing” bibliography. I can still add them to “my library”…

This seems to be related to the referencesTo property of Publication:

java.lang.NullPointerException
	at webdsl.generated.domain.Publication.validateReferencesTo_internal_(Publication.java:2639)
	at webdsl.generated.domain.InProceedings.validateSave_(InProceedings.java:478)
	at webdsl.generated.domain.InProceedings.validateSave(InProceedings.java:24)
	at utils.AbstractPageServlet.validateEntitiesAfterAction(AbstractPageServlet.java:202)
	at webdsl.generated.templates.yourBibAction_s_ad3_s_ad0StringPublicationBibliographyString_Template$1.run(yourBibAction_s_ad3_s_ad0StringPublicationBibliographyString_Template.java:325)

Which version of WebDSL was used?

Can you post the generated Java function webdsl.generated.domain.Publication.validateReferencesTo_internal_(Publication.java:2639)?

Hmm, I thought I already fixed that by updating the properties to be the empty string. I have now run the update again:

mysql> update _Publication set _referencesTo = '' where _referencesTo is NULL;
Query OK, 587 rows affected (17.46 sec)
Rows matched: 587 Changed: 587 Warnings: 0

Apparently since Sunday 587 records lost their _referencesTo field …

Lennart, do you still experience the problem now?

Two out of three still failed :( But it worked after I tried those again a second time!

Sander, Danny, I’ve been doing some experiments to try to improve this behaviour based on the hypothesis that the actual adding the publication to the bibliography was the problem. However, that does not improve the performance. Could you profile this? Is there a database index problem, or is most time spent in Java code?

I tried to experiment a bit with adding publications to a bibliography, but I am not able to reproduce the problem. I tried adding to a near empty bibliography and adding to a larger bibliography. The addition (and removal) are not very fast, but run fine within a second or two. I’ll wait for Lennart to arrive, to take a look at his bibliographies.

There are two variables in this experiment: the size of the bibliography you’re adding to and the total number of bibliographies (and groups) of the principal. I guess you don’t have many bibliographies. Could you create a large bibliography, for instance by copying the contents of a largisch tag to a new bibliography and then manually adding some more publications. If that still does not trigger the problem, than I’m starting to suspect the number of bibliographies in the equation.

I copied a bunch of other bibliographies into one of mine and have a much bigger bibliography now. The publication addition is getting much slower. It takes about five to ten seconds. In this time, Tomcat is using 100% cpu. Additionally, mysql consumes around 20% of cpu at the start of the addition, but slows down about half way through. This suggests that much data is loaded from the database into Tomcat memory, which is confirmed by Tomcat’s memory size, which bounces around a 1G range during the request. All memory can be garbage collected afterwards.

Ok, it is bibliography size after all. Can you see what objects are being loaded (queries executed)? Is it just the set of publications, or more stuff than that?

I guess the Set abstraction is leaky; it shouldn’t load the whole set into memory when adding an object.

There are no long-lasting queries during the requests. Small ones instead, which are hard to spot since they do not last very long (and query logging is turned off). Here are some queries that were executed. Hope they help. Keep in mind though, that some might also originate from other requests, as there is no easy way of distinguishing between requests when just looking at currently executing queries.

select … from PublicationCategory_publications_Publication publicati0_
inner join Publication publicatio1 on publicati0_.publications_id=publicatio1.id
where publicati0_._PublicationCategory_id=‘4d08bf2ccf254cd39de5f0a4b01a7207’

select … from Publication_lists_PublicationList lists0_
inner join PublicationList publicatio1 on lists0_.PublicationList_id_inverse=publicatio1_.id
where lists0_.Publication_id_owner=‘04b09c754dda4550aa7aec96ee3aeccf’

select … from Alias alias0
where alias0_.id=‘f836eab34fdf43be8a782f75bff78fbd’

select … from DBLP_Publication this
where (this_._key=‘conf/icmcs/Hirakawa99’)

update _Publication set …
where id=‘c6b845143abd43ceb2addfb4a4cb8aa6’ and version_opt_lock=8

As each of the queries use specific identifiers, I guess it is primarily object loading that is going on. Of course one could wonder why these objects are not all loaded in one query. Perhaps a result of Hibernate lazily loading an object set (containing identifiers) and is then triggered to load each object separately (perhaps a loop over the set?).

The logsql feature was the savior here, since it allowed us to spot the problem. It turns out that most of the performance issues were due to a couple of access control predicates, which checked for group membership

user in group.members

With the growing number of users of researchr, the check for membership of the allGroup caused all these checks to become increasingly expensive. The simple fix was to turn the query around

group in user.member

Key lesson: analytics!