View Issue Details

IDProjectCategoryView StatusLast Update
0000887bareos-corewebuipublic2019-12-18 15:20
Reportercrs9 Assigned Toarogge  
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionfixed 
PlatformLinuxOSCentOSOS Version7
Product Version17.2.4 
Summary0000887: Restore file list taking 20 minutes to populate
DescriptionWhen selecting a client with a large number of files, the file list will take over 20 minutes to come back. Clicking to other tabs will do nothing until the task is complete.
The bareos-audit.log shows:

20-Dec 11:29 : Console [admin] from [127.0.0.1] cmdline .bvfs_lsdirs jobid=778,804,829 path= limit=1000 offset=0
20-Dec 11:29 : Console [admin] from [127.0.0.1] cmdline .bvfs_update jobid=778,804,829
20-Dec 11:29 : Console [admin] from [127.0.0.1] cmdline .bvfs_lsdirs jobid=778,804,829 path= limit=1000 offset=1000

This appears over and over until it reaches:

20-Dec 11:50 : Console [admin] from [127.0.0.1] cmdline .bvfs_lsdirs jobid=778,804,829 path= limit=1000 offset=10349000
20-Dec 11:50 : Console [admin] from [127.0.0.1] cmdline status director

The Dashboard state 9150221 files, 617 jobs. This specific client has 0000010:0000301,000 files.
If I browse away from this client and back, the count starts all over again.
Steps To ReproduceUpgrade from 17.1.3 to 17.2.4
Manually update db scheme
Log into webui
Select client with a large amount of files to restore from
Additional InformationJorg asked for the following:
}.bvfs_lsdirs jobid=778,804,829 path= limit=1000 offset=0
{
  "jsonrpc": "2.0",
  "id": null,
  "result": {
    "directories": [
      {
        "type": "D",
        "pathid": 45383,
        "fileid": 0,
        "jobid": 0,
        "lstat": "A A A A A A A A A A A A A A",
        "name": ".",
        "fullpath": ".",
        "stat": {
          "dev": 0,
          "ino": 0,
          "mode": 0,
          "nlink": 0,
          "user": "root",
          "group": "root",
          "rdev": 0,
          "size": 0,
          "atime": 0,
          "mtime": 0,
          "ctime": 0
        },
        "linkfileindex": 0
      }
    ]
  }

*.bvfs_lsdirs jobid=778,804,829 path= limit=1000 offset=1000
{
  "jsonrpc": "2.0",
  "id": null,
  "result": {
    "directories": [
      {
        "type": "D",
        "pathid": 45383,
        "fileid": 0,
        "jobid": 0,
        "lstat": "A A A A A A A A A A A A A A",
        "name": ".",
        "fullpath": ".",
        "stat": {
          "dev": 0,
          "ino": 0,
          "mode": 0,
          "nlink": 0,
          "user": "root",
          "group": "root",
          "rdev": 0,
          "size": 0,
          "atime": 0,
          "mtime": 0,
          "ctime": 0
        },
        "linkfileindex": 0
      }
    ]
  }

*.bvfs_lsdirs jobid=778,804,829 path= limit=1000 offset=10349000
{
  "jsonrpc": "2.0",
  "id": null,
  "result": {
    "directories": [
      {
        "type": "D",
        "pathid": 45383,
        "fileid": 0,
        "jobid": 0,
        "lstat": "A A A A A A A A A A A A A A",
        "name": ".",
        "fullpath": ".",
        "stat": {
          "dev": 0,
          "ino": 0,
          "mode": 0,
          "nlink": 0,
          "user": "root",
          "group": "root",
          "rdev": 0,
          "size": 0,
          "atime": 0,
          "mtime": 0,
          "ctime": 0
        },
        "linkfileindex": 0
      }
    ]
  }
TagsNo tags attached.

Relationships

related to 0000890 closed .bvfs_update does not always create all cache enties. This results in a not working webui restore tree 

Activities

crs9

crs9

2018-01-02 21:35

reporter   ~0002854

As a note, from the 16.2.7 notes, I cannot create index

bareos=# CREATE INDEX file_jpfnidpart_idx ON File(PathId,_JobId, _FilenameId) WHERE FileIndex = 0;
ERROR: column "_jobid" does not exist

Not sure if this is required or not.
crs9

crs9

2018-01-02 21:55

reporter   ~0002855

I stand corrected, I see the expected indexes that were created during the 2171 migration
crs9

crs9

2018-01-03 15:49

reporter   ~0002857

I updated the cache manually.
backup01:~$ time echo ".bvfs_update" | sudo bconsole
Connecting to Director localhost:9101
1000 OK: backup01 Version: 17.2.4 (21 Sep 2017)
Enter a period to cancel a command.
.bvfs_update
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
You have messages.

real 1m59.716s
user 0m0.053s
sys 0m0.020s

After only taking 2 minutes, the restore list is still taking 20 minutes to populate.
joergs

joergs

2018-01-04 13:37

developer   ~0002859

There are at least two problems here:

1. the result delivered by .bvfs_lsdirs is not correct. It misses an entry for "/".
2. the bareos-webui does not behave right. The newly introduced looping through the result set continues looping until it receives the full result. In your case this results in an endless loop. I assume, after 20 minutes some browser, ajax or php timeout triggers.

About 2: this will be fixed soon.

About 1: I'm not sure, what triggers the problem in the first place. A few questions to limit the scope:
  * does this happen for all restore jobs or just for a specific one?
  * what database backend do you use?
  * have you used bareos-dbcheck? If not, don't use it now. There is another bug in there, at least when using sqlite. This will also be resolved soon.
crs9

crs9

2018-01-04 14:44

reporter   ~0002860

1) I have 6 clients
backup01, centos7.2 - lists fine
catalog, centos 7.2 - lists fine
dc01, windows 2016 core - lists fine
dc02, windows 2016 core - lists fine
fmp01, windows 2016 - slow - 301975 files, 294GB size
fps01, windows 2016 - slow - 181855 files, 14.11GB size

Both slow servers took 20 minutes to list.

After 20min, the webui displays an error box "Oops, something went wrong, probably too many files"

2) Postgresql 9.6.6

3) I have not used that, should I try it since I'm using postgresql?
joergs

joergs

2018-01-04 14:51

developer   ~0002861

about 3:
not now. I'll first check what exactly the problem with dbcheck is.

about 1:
interesting. I've not assumed this.

What you could do is to recreate the full bvfs cache. Please be aware, that this will take quite a long time.

On bconsole type:
.bvfs_clear_cache yes
.bvfs_update

The first command will be quick, the second will take a lot of time and is normally not required (it will normally be called for specific jobids that you are interested in). However, you should give it a try.

For details about bvfs see http://doc.bareos.org/master/html/bareos-developer-guide.html#sec:bvfs
crs9

crs9

2018-01-04 15:32

reporter   ~0002862

.bvfs_clear_cache yes
ran for 2 seconds

.bvfs_update
ran for 16 minutes

Same slowness and error after the update command.
joergs

joergs

2018-01-04 15:44

developer   ~0002863

Okay, that is the result of

list files jobid=<last full job of fmp01>
crs9

crs9

2018-01-04 15:49

reporter   ~0002864

It list all the files on C: and D:, which I would expect.
crs9

crs9

2018-01-04 15:55

reporter   ~0002865

fmp01 listing took 28 seconds.

fps01 last full lists all it's C: and D: files as expected also. this listing took 27 seconds, even though it has almost 2 times the number of files.
joergs

joergs

2018-01-04 16:04

developer   ~0002866

But how are they displayed?

/C:/...

or somehow else?
crs9

crs9

2018-01-04 16:08

reporter   ~0002867

C:/Users/
 D:/Users/

there is a block of whitespace before each letter. dc01 is displayed the same way.
One other way these two servers are different, they have a D:/, dc01 and 02 do not.
frank

frank

2018-01-04 17:26

developer   ~0002868

Note:

A fix regarding the endless loop in case of receiving rubish BVFS output has been pushed internal to the webui bareos-17.2 branch and is going public with the next push to GitHub as well.
joergs

joergs

2018-01-05 16:56

developer   ~0002869

In my Linux only test environment, I was able to create a similar problem by using dbcheck on my sqlite database.

Following steps did resolve this issue:

# clear cache
.bvfs_clear_cache yes

# restart the bareos-dir
systemctl restart bareos-dir

# update cache
.bvfs_update

The reason is some internal director cache.
frank

frank

2018-01-09 12:31

developer   ~0002871

Fix committed to bareos-webui bareos-17.2 branch with changesetid 7444.
protopopys

protopopys

2018-01-15 06:54

reporter   ~0002873

Hi, it's not working for me. I have a tousen folders in directory and if i want to restore some files i have the error.
protopopys

protopopys

2018-01-15 06:56

reporter  

hostedpower

hostedpower

2018-03-27 13:05

reporter   ~0002953

Same here, cannot restore our machines :(

We're using MySQL and it's sooooo slow again. Don't know what happened.
hostedpower

hostedpower

2018-03-27 13:15

reporter   ~0002955

Ok server reboot fixed it here for us, no idea why it was so damn slow before the reboot.
joergs

joergs

2018-04-05 12:39

developer   ~0002958

I assume, the problems are fixed with Bareos 17.2.5. Note: updating both the webui and the director is required.

Did anybody have other experiences with bareos-17.2.5?
arogge

arogge

2019-12-10 14:25

manager   ~0003651

Is anyone still able to reproduce this problem?
hostedpower

hostedpower

2019-12-10 14:32

reporter   ~0003653

working fine atm, main solution I think is proper indexing in MySQL and we also run .bvfs_update automatically.

An INSANELY fast disk with high iops for the database tends to help as well for the overall performance, also during backups.
arogge

arogge

2019-12-10 14:45

manager   ~0003656

If everything works, I'm going to set this to resolved.

Related Changesets

bareos-webui: bareos-17.2 a562e5fe

2018-01-04 18:13

frank

Ported: N/A

Details Diff
Fix to bugreport 0000887

The newly introduced looping through the result set continues looping until it receives the full result.
There was a case that lead to an endless loop, if the BVFS API delivers a rubish result.

Fixes 0000887: Restore file list taking 20 minutes to populate
Affected Issues
0000887
mod - CHANGELOG.md Diff File
mod - module/Restore/src/Restore/Model/RestoreModel.php Diff File

Issue History

Date Modified Username Field Change
2017-12-28 15:06 crs9 New Issue
2018-01-02 21:35 crs9 Note Added: 0002854
2018-01-02 21:55 crs9 Note Added: 0002855
2018-01-03 15:49 crs9 Note Added: 0002857
2018-01-04 13:29 joergs Assigned To => frank
2018-01-04 13:29 joergs Status new => assigned
2018-01-04 13:37 joergs Note Added: 0002859
2018-01-04 14:44 crs9 Note Added: 0002860
2018-01-04 14:51 joergs Note Added: 0002861
2018-01-04 15:32 crs9 Note Added: 0002862
2018-01-04 15:44 joergs Note Added: 0002863
2018-01-04 15:49 crs9 Note Added: 0002864
2018-01-04 15:55 crs9 Note Added: 0002865
2018-01-04 16:04 joergs Note Added: 0002866
2018-01-04 16:08 crs9 Note Added: 0002867
2018-01-04 17:26 frank Note Added: 0002868
2018-01-05 16:52 joergs Assigned To frank => joergs
2018-01-05 16:56 joergs Note Added: 0002869
2018-01-05 16:56 joergs Status assigned => feedback
2018-01-08 21:56 joergs Relationship added related to 0000890
2018-01-09 12:31 frank Changeset attached => bareos-webui bareos-17.2 a562e5fe
2018-01-09 12:31 frank Note Added: 0002871
2018-01-09 12:31 frank Status feedback => resolved
2018-01-09 12:31 frank Resolution open => fixed
2018-01-09 12:31 frank Status resolved => feedback
2018-01-09 12:31 frank Resolution fixed => reopened
2018-01-15 06:54 protopopys Note Added: 0002873
2018-01-15 06:56 protopopys File Added: Снимок экрана от 2018-01-15 09-51-07.png
2018-03-27 13:05 hostedpower Note Added: 0002953
2018-03-27 13:15 hostedpower Note Added: 0002955
2018-04-05 12:39 joergs Note Added: 0002958
2018-04-05 12:39 joergs Status feedback => assigned
2019-09-27 16:41 joergs Assigned To joergs =>
2019-12-10 14:25 arogge Status assigned => feedback
2019-12-10 14:25 arogge Note Added: 0003651
2019-12-10 14:32 hostedpower Note Added: 0003653
2019-12-10 14:45 arogge Assigned To => arogge
2019-12-10 14:45 arogge Status feedback => resolved
2019-12-10 14:45 arogge Resolution reopened => fixed
2019-12-10 14:45 arogge Note Added: 0003656
2019-12-18 15:20 arogge Status resolved => closed