GNOME Bugzilla – Bug 342439
GetNextProperty does not find "speakingto_alias"
Last modified: 2006-06-16 18:49:37 UTC
Please describe the problem: Trying to fix http://bugzilla.gnome.org/show_bug.cgi?id=160328... Joes Patch uses GetNextProperty to get the alias. But it does not return anything even though beagle-query --verbose lists it. Steps to reproduce: 1. Patch current CVS with my patch as attached to 160328 2. Search for a line from an IM log 3. look at the from field Actual results: No Alias is found, Debug line in Hit.cs prints Could not find Key: fixme:speakingto_alias not equal fixme:starttime Expected results: Alias should be found Does this happen every time? yes Other information: yes ;) Looks like the Algo in beagle-client/Hit.cs causes this. FindProperty does not seem to find the right key. This might be due to the underscore in speakingto_alias. beagle-query --verbose prints beagle:HitType = IMLog beagle:MimeType = beagle/x-gaim-log beagle:Source = GaimLog fixme:client = gaim fixme:endtime = 20060520193831 fixme:identity = nochntestgggh@jabber.org fixme:protocol = jabber fixme:speakingto = instanttest@jabber.org fixme:starttime = 20060520192520 fixme:speakingto_alias = Max Wiehle Which is not sorted alphabetically in the last three lines. The rest is. I'm not sure if it should be sorted but FindProperty trying to return fixme:starttime instead of speakingto_alias looks like thats the problem.
Created attachment 65909 [details] [review] patch to debug Hit.cs as described above Checking why speakingto_alias is not found.
Looks like Sorting in Hit.cs is never done because sorted is always set to 1. If i force a sort before every find it works.
Sorting is done sometimes - that's not the bug. I tryed to debug a little more and it almost looks like it's out of sync... All calls to FindProperty report the Key and all calls to AddProperty are reported as well... This is a search with two results. Adding Property... beagle:HitType Adding Property... beagle:MimeType Sorted and not empty... Adding Property... beagle:Source Sorted and not empty... Adding Property... fixme:starttime Sorted and not empty... Adding Property... fixme:endtime Sorted and not empty... Unsorted Properties... Adding Property... fixme:client Adding Property... fixme:protocol Adding Property... fixme:speakingto Adding Property... fixme:identity Searching for... beagle:HitType Sorting Properties... Searching for... beagle:MimeType Searching for... beagle:Source Adding Property... beagle:HitType Adding Property... beagle:MimeType Sorted and not empty... Adding Property... beagle:Source Sorted and not empty... Adding Property... fixme:starttime Sorted and not empty... Adding Property... fixme:endtime Sorted and not empty... Unsorted Properties... Adding Property... fixme:client Adding Property... fixme:protocol Adding Property... fixme:speakingto Adding Property... fixme:identity Searching for... beagle:HitType Sorting Properties... Searching for... beagle:MimeType Searching for... beagle:Source Searching for... fixme:speakingto Searching for... fixme:speakingto_alias Could not find Key: fixme:speakingto_alias not equal fixme:starttime Adding Property... fixme:speakingto_alias Sorted and not empty... Unsorted Properties... Searching for... fixme:speakingto Searching for... fixme:speakingto_alias Could not find Key: fixme:speakingto_alias not equal fixme:starttime Adding Property... fixme:speakingto_alias Sorted and not empty... Unsorted Properties...
The above output (#3) is from beagled. So it's not the search itself but rather building the Hit. speakingto_alias is added to the hit in GaimLogQueryable using hit["fixme:speakingto_alias"] = buddy.Alias This causes these lines: Searching for... fixme:speakingto_alias Could not find Key: fixme:speakingto_alias not equal fixme:starttime Adding Property... fixme:speakingto_alias Sorted and not empty... Unsorted Properties... Using ["key"] makes the hit look for the key first and then add it if it does not exist. That's where the Could not find line is coming from. Adding the speakingto_alias sets sorted to false but when beagle-search calls GetFirstProperty sorted is reported to be true: Searching for... fixme:starttime Sorted: True beagle:HitType = IMLog beagle:MimeType = beagle/x-gaim-log beagle:Source = GaimLog fixme:client = gaim fixme:endtime = 20060520193831 fixme:identity = nochntestgggh@jabber.org fixme:protocol = jabber fixme:speakingto = instanttest@jabber.org fixme:starttime = 20060520192520 fixme:speakingto_alias = Max Wiehle Searching for... fixme:speakingto_alias Sorted: True Could not find Key: fixme:speakingto_alias not equal fixme:starttime Obviously the keys have been sorted before speakingto_alias was added. When it was added sorted was set to false. But when GetFirstProperty is called sorted is set to true without having sorted anything. Maybe the Hit has been copyed in a way that did not copy the sorted value. sorted defaults to true. If you change the default to false in BeagleClient/Hit.cs the search works. I will create a patch that does this. It changes the behaviour of Hit.cs to not think of the empty properties as a sorted list but as an unsorted one. So all new properties are added not comparing to the last one to see if it's still sorted. When it is searched for the first time it will be sorted. Afterwards new properties will be compared to see if it's still sorted just like before. The only difference is the begining. We gain some speed by not comparing all new properties to the last one. We only loose (a lot more) speed if before the first search all properties have been added in alphabetical order. But then the sort algorithm should be pretty fast anyway (? - i got no idea which one they use)...
Created attachment 65955 [details] [review] Workaround defaulting sorted to false This patch also uses StringFu.CleanupInvalidXmlCharacters on keys because that's also done when storing keys in the database. Not Cleaning it up did not cause any problems to me but who knows. We want to compare the key strings so i think we better clean both up.
Created attachment 66686 [details] [review] Add properties to GaimLog queriables properly Ok, I think that this should (more or less) fix the problem you have found, let me know if it doesn't, but I think the core issue was that we were not adding the speakingto_alias property properly, so it was not being sorted by our methods when going in. Again, as my Gnome Account gets closer and closer, I can probably commit this as one of my 'learn CVS' moments.
Ok, I think its fixed in CVS, but please feel free to reopen should this resurface, I don't think it was an issue with our search algorithm as much as it was an issue with how properties were being added in the GaimLog backend.
Sorry Kevin, have been too busy during the last days to check but actually it does not seem to work for me. Tryed latest cvs with the beagle-search patch on http://bugzilla.gnome.org/show_bug.cgi?id=160328 but aliases still are not being found. beagle-query still returns an unsorted list (this is not a problem it self just a hint that the issue persists): beagle:HitType = IMLog beagle:MimeType = beagle/x-gaim-log beagle:Source = GaimLog fixme:client = gaim fixme:endtime = 20060529133220 fixme:identity = mawx@jabber.org fixme:protocol = jabber fixme:speakingto = kwa@jabber.org fixme:starttime = 20060529123031 fixme:speakingto_alias = Kyle querying for this entry with beagle-search does not find the speakingto_alias property. I'm pretty sure it's the same issue as before. hit ["fixme:speakingto_alias"] internally calls hit.AddProperty() so i think calling that directly doesn't change anything.
Created attachment 67256 [details] [review] Fixes sorting alg in AddProperty so speakingto_alias is in correct place Ok, I'm gonna shamelessly copy my e-mail to the list here.... Ok, this has been a royal-pain-in-the-ass bug to track down. Bug # 342439. Here's the rundown, after about an hour of meticulously debugging the complex FindProperty method, I just decided that things weren't being sorted according to their CompareTo's (which were being used in the sort). And I realized that our method for determining if the array was sorted was faulty. So, I present! Le Patch! I left most of my commented out stuff in there so you could see what was being replaced etc. Because this is such a major part of the beagle system, I wanna make sure it works before we do anything, so please, be thorough. So yeah, AddProperty() used to add the property to the end of the array, and check if the array was sorted, if it wasn't, then beagle simply waited until someone was looking for those properties. The replacement inserts the properties in sorted order as they are added, which cost's a little more time on the indexing side, but saves us a sort when querying.
Created attachment 67259 [details] [review] Fix a mistake in new sorting alg. Fixed a >< typo.
> 342439. Here's the rundown, after about an hour of meticulously > debugging the complex FindProperty method, I just decided that things > weren't being sorted according to their CompareTo's (which were being The CompareTo of properties sorts the properties based on key first and then value. FindProperty does the same. > So yeah, AddProperty() used to add the property to the end of the array, > and check if the array was sorted, if it wasn't, then beagle simply > waited until someone was looking for those properties. Thats "lazy-sorting". Since sorting is expensive, and clients might not touch some hits at all, it saved a few sortings. I'm trying to figure out why the "method for determining if the array was sorted was faulty". The code in Hit.cs looks ok to me at first glance. I will give it another read. In your patch, you are doing a linear scan to find the place to insert. If you always maintain arraylist as sorted, then you can binarysearch to find the place to insert instead of linear scanning for the position.
> Obviously the keys have been sorted before speakingto_alias was added. When it > was added sorted was set to false. But when GetFirstProperty is called sorted > is set to true without having sorted anything. Maybe the Hit has been copyed in Can you confirm this ? Add some debug statements here and there, maybe print the list in order to see the keys. I am not in a position to build the code, let alone run it. Ideally, GetFirstProperty -> FindProperty -> properties.sort() should sort the list on any access. Wondering what is wrong! > I will create a patch that does this. It changes the behaviour of Hit.cs to not > think of the empty properties as a sorted list but as an unsorted one. > So all new properties are added not comparing to the last one to see if it's > still sorted. > When it is searched for the first time it will be sorted. Afterwards new > properties will be compared to see if it's still sorted just like before. > The only difference is the begining. We gain some speed by not comparing all > new properties to the last one. We only loose (a lot more) speed if before the > first search all properties have been added in alphabetical order. But then the This optimization actually makes sense. But it shouldnt affect the bug, though.
In the original code, we had a loop that looked something like this: if (sorted && properties.Count > 0) { Property last_prop; last_prop = properties [properties.Count - 1] as Property; if (last_prop.CompareTo (prop) > 0) {// i.e. last_prop > prop Console.WriteLine ("In AddProperty: " + last_prop + " to " + prop+ " result: " +last_prop.CompareTo (prop)); sorted = false; } } I can't be certain, but with literally near 100 Console.WriteLines to help me debug, all I could narrow it down to was that this if statement was not always setting sorted correctly, and that there were times when a property would be out of place (like speakingto_alias) and sorted would still equal true. I think its because the second if always compares only the last value, but its hard to say. I would have thought that this would work, but it doesn't.
Im pretty sure it is NOT the IF clause. I think i did not explain well what i found out to track it down in comments #3 and #4 so i will try again... I had a debug line in the if clause that would print Unsorted Properties... Up in comment #3 you can read beagleds output. Here's what it says with some comments from my side (the last lines are interesting): We were calling hit["fixme:speakingto_alias"] = buddy.Alias in GaimLogQA This looks for the property and then sets it: Searching for... fixme:speakingto_alias Could not find Key: fixme:speakingto_alias not equal fixme:starttime Adding Property... fixme:speakingto_alias Sorted and not empty... <- First If clause Unsorted Properties... <- Second... The last line shows that sorted has been set to false (it was printed from within the if clause and i also checked sorted). Now later on from a different Place (HitFilter) we search for the properties and don't sort them because here it looks like sorted is true. So we don't find it. The debug output is in comment #4 - this time it's from beagle-client: Searching for... fixme:starttime Sorted: True beagle:HitType = IMLog beagle:MimeType = beagle/x-gaim-log beagle:Source = GaimLog fixme:client = gaim fixme:endtime = 20060520193831 fixme:identity = nochntestgggh@jabber.org fixme:protocol = jabber fixme:speakingto = instanttest@jabber.org fixme:starttime = 20060520192520 fixme:speakingto_alias = Max Wiehle Searching for... fixme:speakingto_alias Sorted: True Could not find Key: fixme:speakingto_alias not equal fixme:starttime Now sorted is "True" even though it has been set to false before and the properties obviously have not been sorted. I think somewhere in between the Hit has been copied or so and that has set sorted to it's initial state which was true. That's the only way i can explain that defaulting sorted to false like here: http://bugzilla.gnome.org/attachment.cgi?id=65955 solved it for me. Maybe this helps to track down the issue - i think i don't know enough about what happens to the Hit between GLQ and HitFilter to do so.
> > I will create a patch that does this. It changes the behaviour of Hit.cs to not > > think of the empty properties as a sorted list but as an unsorted one. > > So all new properties are added not comparing to the last one to see if it's > > still sorted. > > When it is searched for the first time it will be sorted. Afterwards new > > properties will be compared to see if it's still sorted just like before. > > The only difference is the begining. We gain some speed by not comparing all > > new properties to the last one. We only loose (a lot more) speed if before the > > first search all properties have been added in alphabetical order. But then the > > This optimization actually makes sense. But it shouldnt affect the bug, though. > It did for me. I will get a clean beagle from cvs, put the patch in and try again. But i am 99 % sure. And i am also quite sure this is relevant for finding the bug - that's why i am insisting so much -- sorry if i am a little too loud...
Awesome, good to know we might have finally nailed this one down ;) I'm gonna try some more tests, specifically with the other backends to make sure there are no issues. We could make this a binary search like D Bera suggested, although, after the long battle it took to find this one, I would really rather stick to the old-school Unix philosophy on this one and get it working rock solid and right before we look to intently into performance. (Don't get me wrong, we should be aware of performance) but yeah, my $0.02. Assuming we don't run into any major errors, I'll post a cleaned up version of the patch in a little bit and well consider committing.
> The last line shows that sorted has been set to false (it was printed from > within the if clause and i also checked sorted). > > Now later on from a different Place (HitFilter) we search for the properties > and don't sort them because here it looks like sorted is true. So we don't find > it. > The debug output is in comment #4 - this time it's from beagle-client: > > Searching for... fixme:starttime > Sorted: True > beagle:HitType = IMLog > beagle:MimeType = beagle/x-gaim-log > beagle:Source = GaimLog > fixme:client = gaim > fixme:endtime = 20060520193831 > fixme:identity = nochntestgggh@jabber.org > fixme:protocol = jabber > fixme:speakingto = instanttest@jabber.org > fixme:starttime = 20060520192520 > fixme:speakingto_alias = Max Wiehle > Searching for... fixme:speakingto_alias > Sorted: True > Could not find Key: fixme:speakingto_alias not equal fixme:starttime > > Now sorted is "True" even though it has been set to false before and the > properties obviously have not been sorted. I think somewhere in between the Hit > has been copied or so and that has set sorted to it's initial state which was > true. Thanks. Now I know whats messing it. Here is the story. beagled and beagleui are two separate processes which communicate via XML messaging. The properties arraylist is sent via xml node-array. The property "sorted" is not sent via xml. So, when beagled is sending the property arraylist, it is unsorted. But when UI (beagleclient from UI) accesses the arraylist, sorted is default set to true and so it thinks the list is sorted. A minor issue indeed ;-) FindProperty and AddProperty has lots of scope for optimization. A careful optimization will also remove the sorting fiasco and get rid of the bug altogether. Since I dont have the source with me here, I will repost what code changes are needed.
Alright, sounds good enough. I was thinking just cheating a bit and using the ArrayList.BinarySearch() method and using that to find any middle position.
To get rid of all confusion, and maintain compatibility with libbeagle, we need to change the code to make sure the arraylist is always sorted - no more lazy sorting. That is, each addition to the list will maintain the sorted property. Use some smart insertion rather than linear scan of the arraylist. That needs to be followed up by removal of the variable "sorted" and general cleanup of the code. That should cleanup the confusion and fix the bug. As I said before, I cant build the source. Someone needs to cook up a patch and do some basic testing (test GaimQ and some other backends as well).
Created attachment 67292 [details] [review] Cleaned up and commented code. Ok, we may not end up using this code, but I've tested it pretty thoroughly and I can't say I've had any problems so well see. Regardless, this copy is significantly cleaner and has some nice comments.
Created attachment 67300 [details] [review] Significantly Optimized Ok, heres the convo that should pretty much explain it: (04:58:34 PM) kkubasik: ok, I've got a nice prototype (04:59:11 PM) kkubasik: http://pastebin.com/707359 (05:02:24 PM) dBera: kkubasik: you shouldnt need the special case for 0 and last (05:02:56 PM) ma1: kkubasik: cool - this BinarySearch looks interesting. Guess we could also use it when finding properties - we are doing the same by hand now. (05:03:13 PM) dBera: o/w it looks ok 17:03 (05:03:21 PM) kkubasik: dBera: you mean the first 3 special cases? (05:03:30 PM) dBera: 2nd and 3rd special case (05:03:33 PM) dBera: 1st is fine (05:03:36 PM) kkubasik: those are just to avoid the Binary search if we can (05:03:39 PM) kkubasik: they aren't needed (05:03:52 PM) kkubasik: but if we can skip calling the search for something easy like that (05:04:14 PM) dBera: its not worth it. the code would be easier to follow (05:04:48 PM) ma1: We could also try and avoid searching the property first and then adding it when using hit["fixme:speakingto_alias"] (05:04:56 PM) dBera: binasysearch code would do someting like that anyway (05:06:19 PM) ma1: just my $0.02 - gotta leave and clean up our kitchen now :( (05:06:25 PM) kkubasik: if I remove those special cases we get like 2000 indexed out of bounds errors, i guess we gotta keep them.
I agree with Bera: the first element and last element optimizations should be removed unless we are pretty certain that in a non-trivial number of cases this would be true. "Don't prematurely optimize," the old adage goes. If there are out of bounds errors, then there's probably a bug in the code, which there is. :) A negative return value from BinarySearch() is not the negative of where it would be inserted, but the bitwise complement of where it would be inserted: http://msdn2.microsoft.com/en-us/library/5tzt7yz3.aspx So what you want instead of "loc = loc * -1;" (which could have been written "loc = -loc;") is "loc = ~loc;" (tilde). Also style fixes needed. For example: //if its the smallest, then were done! if ( prop.CompareTo (properties[0]) < 0){ should be: // If it's the smallest, then we're done! if (prop.CompareTo (properties [0]) < 0) { etc. I would probably also add blank lines between each of the comparisons to make it look less cramped.
LuceneCommon does a AddProperty(Property) in a loop. It doesnt make sense to sort, insert, sort, insert, sort, insert, for all 20 properties. The previous approach was guarded against such inefficiencies. So, I suggest a AddProperties (IList propertylist) in Hit.cs to batch insert a bunch of properties. Basically add all of them at front/end and sort only once at the end. Use it from LuceneCommon:AddPropertiesToHit() in the following way: static protected void AddPropertiesToHit (Hit hit, Document doc, bool from_primary_index) { ArrayList properties; foreach (Field f in doc.Fields ()) { Property prop; prop = GetPropertyFromDocument (f, doc, from_primary_index); if (prop != null) properties.Add (prop); } hit.AddProperties (properties); }
Created attachment 67301 [details] [review] Cleaned up and using a bitwise conversion. Ok, any and everyone, let me know what you think.
Sorry to be bothering :( and picky. I am trying to sanitize the code. 1) Can this ever occur ? loc >= 0 ? And is the logic ok in that case. I am delegating my part of thinking to you :) 2) Is the flag "sorted" used anywhere else in the code ? It shouldnt be and the variable should be removed. 3) Do we even need the "if (properties.Count == 0) {" case ? I would assume properties.BinarySearch() would return 0 in that case anyway. Rest looks good. Add the AddProperties (IList properties) method to Hit.cs and everything should be ok to go in.
(In reply to comment #25) > Sorry to be bothering :( and picky. I am trying to sanitize the code. > > 1) Can this ever occur ? loc >= 0 ? And is the logic ok in that case. I am > delegating my part of thinking to you :) Yes, whenever we have more than one property that is the same, its not common, but especially on things like .desktop files where we index 50 some properties (most of which are translations) its possible to have identical s. > 2) Is the flag "sorted" used anywhere else in the code ? It shouldnt be and the > variable should be removed. Agreed, I was tenative to remove it until there was a complete censue on the removal of our lazy-sort, and then I forgot... > 3) Do we even need the "if (properties.Count == 0) {" case ? I would assume > properties.BinarySearch() would return 0 in that case anyway. I'm not sure about this one, I'll have to check. > Rest looks good. > Add the AddProperties (IList properties) method to Hit.cs and everything should > be ok to go in. > Ok, should be easy enough, probably won't get to all this until a little later. I;m going out of town with the girlfriend for a couple of days.
Created attachment 67492 [details] [review] Updated patch. Went ahead and tweaked it up and committed this patch. Thanks guys!