Very slow content updating - edited

[DavidHoffmanuk]

I don't expect any problems, but I don't know what caused the problem in the first place.  I suggest letting the remove operation complete fully (see that the tasks all become idle).  Then quit Photo Mechanic Plus and backup the db again, then do the full sync.  Normally I wouldn't suggest any of that but something is going on with the previous catalog and you may as well have a backup at a known good state.

OK, thanks. I'll give it a slow try. I was very likely starting new operations while old ones were still in progress.

I've just seen your pmdb question - yes, there's a 5.62GB one there though it has a mod date of 2021.

That's very strange.  Could a restore from a backup have occurred at some point during this process?

I quit PM+, removed the folder with the non-functional pmdb and replaced it with the equivalent one from a backup. That gave exactly the same problem when I restarted PM+ so I quit again, removed the backup version and replaced the original folder. That made no difference as would be expected since I now know that the cat_state.sq3 file would have started the same stalled operations.

It's all looking positive and I just need to be p a t i e n t.

David
-

[DavidHoffmanuk]

I've selected all the 143,051 missing files, added them to a collection and sorted by path to check that these were only the ones I had moved. I selected them all and selected 'remove from catalog'.

The process seems to be running OK, about 100% CPU usage in activity monitor but after 8 hours, the task panel is showing 'updating 1 catalog, 2527 batches remaining (0/sec, est. 2.3 days)'. The number of batches has reduced by just 6 in about 7 minutes.

I still have debug logging turned on and I'm wondering if that's slowing things down. Would it be a good idea to stop the task, turn off the logging and then start again on the removal of missing files? I'm nervous about interfering with any ongoing process after the problem last time.

Is there anything else I might try in order to speed this up?

David

[DavidHoffmanuk]

A bit more info:

Mac Pro 10.14.6. There's 56 Gb of RAM. PM+ and 2 x pm-task are currently using about 5GB. There's about 17GB shown as 'cached files', I assume that's PM+. No swap being used. The Tasks panel looks unhappy to me. I've attached a screenshot going back a few hours. The text in the window doesn't wrap so only the first part of each line is visible. I've selected and pasted the last few lines in their entirety below.

Maybe there are some clues?

David


Tue 13:55:38] Error: RPCServerConn.rpc_dispatch: exception: CILA::PROTO::RPCException/apply_change_journal_batch failed: [:rpc_timeout] to=924880 msg="apply_change_journal_batch" location=/Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:649:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:665:in `method_missing', ./archive/common/catalog.rb:295:in `do_apply_change_journal_batch', ./archive/common/catalog.rb:199:in `block in apply_change_journal_batch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/syncwaiter.rb:85:in `synchronize', ./archive/common/catalog.rb:198:in `apply_change_journal_batch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc_object.rb:72:in `block in initialize', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `block in do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `catch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1062:in `block in rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `block in add_fiber'
[Tue 13:55:38] Error: CatalogMetadataUpdateTask.try_spawn_metadata_update: apply_change_journal_batch failed: [:rpc_timeout]
[Tue 13:55:43] Error: RPCServerConn.rpc_dispatch: exception: CILA::PROTO::RPCException/count_documents failed: [:rpc_timeout] to=924878 msg="query_num_documents" location=/Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:649:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:665:in `method_missing', ./archive/common/catalog.rb:137:in `query_num_documents', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc_object.rb:72:in `block in initialize', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `block in do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `catch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1062:in `block in rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `block in add_fiber'
[Tue 14:06:25] Error: RPCServerConn.rpc_dispatch: exception: CILA::PROTO::RPCException/apply_change_journal_batch failed: [:rpc_timeout] to=924880 msg="apply_change_journal_batch" location=/Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:649:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:665:in `method_missing', ./archive/common/catalog.rb:295:in `do_apply_change_journal_batch', ./archive/common/catalog.rb:199:in `block in apply_change_journal_batch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/syncwaiter.rb:85:in `synchronize', ./archive/common/catalog.rb:198:in `apply_change_journal_batch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc_object.rb:72:in `block in initialize', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `block in do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `catch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1062:in `block in rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `block in add_fiber'
[Tue 14:06:25] Error: CatalogMetadataUpdateTask.try_spawn_metadata_update: apply_change_journal_batch failed: [:rpc_timeout]
[Tue 14:06:30] Error: RPCServerConn.rpc_dispatch: exception: CILA::PROTO::RPCException/count_documents failed: [:rpc_timeout] to=924878 msg="query_num_documents" location=/Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:649:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:665:in `method_missing', ./archive/common/catalog.rb:137:in `query_num_documents', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc_object.rb:72:in `block in initialize', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `block in do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `catch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1062:in `block in rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `block in add_fiber'
[Tue 14:17:14] Error: RPCServerConn.rpc_dispatch: exception: CILA::PROTO::RPCException/apply_change_journal_batch failed: [:rpc_timeout] to=924880 msg="apply_change_journal_batch" location=/Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:649:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:665:in `method_missing', ./archive/common/catalog.rb:295:in `do_apply_change_journal_batch', ./archive/common/catalog.rb:199:in `block in apply_change_journal_batch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/syncwaiter.rb:85:in `synchronize', ./archive/common/catalog.rb:198:in `apply_change_journal_batch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc_object.rb:72:in `block in initialize', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `block in do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `catch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1062:in `block in rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `block in add_fiber'
[Tue 14:17:14] Error: CatalogMetadataUpdateTask.try_spawn_metadata_update: apply_change_journal_batch failed: [:rpc_timeout]
[Tue 14:17:19] Error: RPCServerConn.rpc_dispatch: exception: CILA::PROTO::RPCException/count_documents failed: [:rpc_timeout] to=924878 msg="query_num_documents" location=/Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:649:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:665:in `method_missing', ./archive/common/catalog.rb:137:in `query_num_documents', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc_object.rb:72:in `block in initialize', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1114:in `block in do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `catch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1113:in `do_rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/proto/rpc.rb:1062:in `block in rpc_dispatch', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `call', /Applications/Photo Mechanic Plus PM6+/Photo Mechanic Plus.app/Contents/pmruby/lib/ruby/site_ruby/2.2.0/cila/fiberpool.rb:60:in `block in add_fiber'

[Kirk Baker]

David,

The RPC timeouts have returned.  How many pm-tasks are currently running?  There should be four.

Quitting and restarting Photo Mechanic Plus will likely get things going again.  Logging shouldn't cause enough overhead to make a difference.

-Kirk

[DavidHoffmanuk]

4 pm-tasks. ~99%, ~7.5%, 0%, 0%.

I'll restart.

Any idea as to what may be behind the timeouts?

David

[Kirk Baker]

David,

Any idea as to what may be behind the timeouts?

No, no idea.

-Kirk

[DavidHoffmanuk]

Hi Kirk

I've got the catalog working now and have added the files from their new locations. I still have a problem trying to remove around 100k 'missing' files - the ones that I moved/deleted outside of PM.

Trying to remove them all at once or even just a few hundred almost always fails with PM+ stalled after removing just a few - always a multiple of 25. When that happens the only way that I can get going is to force quit, delete the cat_state.sq3 file (as you suggested), open PM+ & reintegrate (30-40 minutes). For now I'm just living with these ghost files scattered among my search results and collections but can you suggest a way to remove them.

Another thing that may be connected is that I'm seeing an unknown number of files (at least 279 in a set of 868 from an event that I've been working with just now) that appear to be duplicates of existing raw files but with spaces in the filename and their path begins amdoc/// followed by a long alphanumeric string & the filename. They have almost no metadata and I can't edit them, reveal them in the finder or rename them. They have green dots but must also be ghosts. I can remove them without problems but finding them needs a sort by path which is horrifically slow.

David

[Kirk Baker]

David,

You could try doing a reindex maintenance operation.  While it will take some time to complete the indexing, it also performs a number of cleanup tasks that may correct the issue.  Make sure you don't have any unfinished tasks going before doing the reindex.

-Kirk

[DavidHoffmanuk]

Thanks Kirk, I'll give it a try overnight.

I have a mix of about 300 missing files and 300 that are located but 'sort by path' doesn't separate them. Is that to be expected when files are missing?

David

[Kirk Baker]

David,

Thanks Kirk, I'll give it a try overnight.

I have a mix of about 300 missing files and 300 that are located but 'sort by path' doesn't separate them. Is that to be expected when files are missing?

I'm not sure what you mean by 'separate them'?  You're creating a custom sort using the {path} variable?  What shows up if you use the {path} variable in your Info Text on these images?

-Kirk

[DavidHoffmanuk]

David,

Thanks Kirk, I'll give it a try overnight.

I have a mix of about 300 missing files and 300 that are located but 'sort by path' doesn't separate them. Is that to be expected when files are missing?

I'm not sure what you mean by 'separate them'?  You're creating a custom sort using the {path} variable?

Yes, a custom sort with {path}. The missing files have a different path to the located files - there's an additional folder in the path for the located set. If I sort by path then the (otherwise identical) files are sorted so that all the missing are together and I can select & remove. But when I do this sort the order of the files does not change.

 

What shows up if you use the {path} variable in your Info Text on these images?

You mean just write it in a field and see what gets returned? Would that be different from what i see at the bottom of the contact sheet? I can't do that at present as it's busy reindexing. My fingers are crossed that it's done by morning!

David

[Kirk Baker]

David,

Thanks Kirk, I'll give it a try overnight.

I have a mix of about 300 missing files and 300 that are located but 'sort by path' doesn't separate them. Is that to be expected when files are missing?

I'm not sure what you mean by 'separate them'?  You're creating a custom sort using the {path} variable?

Yes, a custom sort with {path}. The missing files have a different path to the located files - there's an additional folder in the path for the located set. If I sort by path then the (otherwise identical) files are sorted so that all the missing are together and I can select & remove. But when I do this sort the order of the files does not change.

Likely due to {path} evaluating to an empty string and the sort code using the filename as a fallback.

What shows up if you use the {path} variable in your Info Text on these images?

You mean just write it in a field and see what gets returned? Would that be different from what i see at the bottom of the contact sheet? I can't do that at present as it's busy reindexing. My fingers are crossed that it's done by morning!

No.  No changes to your metadata.  "Info Text" is described here:

https://docs.camerabits.com/support/solutions/articles/48001144384-the-preview-window#The-Info-Pane

You could add the {path} variable to your Info Text and then open up the Preview window on one of these images, or turn on the Info Tooltips (View->Show Info Tooltips) and see what it says the path is.

-Kirk

[DavidHoffmanuk]

Hi Kirk

The reindex maintenance operation ran OK and the ghost files that were shown as in an 'amdoc' folder and with the spaces in their names replaced by %20 have gone.

The info text shows the same path for the missing files as is shown at the bottom of the contact sheet. Here's a typical pair:

Present file
Date: 14/08/2010
Time: 12:29:35
Path /Volumes/RAWs/Raws from Perky/Raw files to burn/100814 EDL Ahava/100814 EDL Ahava 01.NEF

Missing file
Date: 14/08/2010
Time: 12:29:35
Path /Volumes/Perky/Raw files to burn/100814 EDL Ahava/100814 EDL Ahava 01.NEF

The rest of the info text is the same for each except that the ICC profile for the present file is shown as Adobe RGB (1998) and for the missing file as sRGB Profile. They should all be Adobe RGB (1998). It's not a problem but odd.

Sort by path doesn't work on sets of images that contain both missing and present files but this does not seem to be due to {path} evaluating to an empty string. Sort by path does work on sets containing only missing or only present images.

I've made a subset of 579 files, there are 280 missing files in that. The missing files are all NEF raw files. I can select these and remove them. The Tasks panel shows 12 batches remaining and clears after 20 minutes, the 280 missing files have gone and the Catalog status panel shows similar errors to those I pasted previously.

I can now remove the missing files but it takes an impractically long time. The 280 files above took ~20 minutes and I have almost 100,000. At the same rate that would take 5 days. I've just tried another a batch and the removal time seems consistent at ~4.5 seconds/file. Is that to be expected?

I'll be away from early afternoon today until the morning so I've made a set of about 12,000 files to remove when I leave. If all works as before they should be gone by about 07:00 tomorrow.

To summarise:
I can't sort a mix of missing and present files by path.
Removing missing files takes a frustratingly long time with the catalog out of action.

David

[Kirk Baker]

David,

I can now remove the missing files but it takes an impractically long time. The 280 files above took ~20 minutes and I have almost 100,000. At the same rate that would take 5 days. I've just tried another a batch and the removal time seems consistent at ~4.5 seconds/file. Is that to be expected?

No.

I can't sort a mix of missing and present files by path.

Can you post what you're using for your primary and secondary values in your 'sort by path'?

-Kirk

[DavidHoffmanuk]

David,

I can now remove the missing files but it takes an impractically long time. The 280 files above took ~20 minutes and I have almost 100,000. At the same rate that would take 5 days. I've just tried another a batch and the removal time seems consistent at ~4.5 seconds/file. Is that to be expected?

No.

I was hoping not. Any thoughts as to what I might try to speed this up?

I can't sort a mix of missing and present files by path.

Can you post what you're using for your primary and secondary values in your 'sort by path'?

You've cracked it! I've been ignoring those options and sorting had seemed to work fine other than in this recent case. Primary was {fbas}, secondary blank. I've made primary {path} and secondary {fbas} - it's now doing what I'd expected. Thanks!

David