Bug 1393270

Michal - isn't this table limited to the number of VMs?
What makes it grow and grow?

Eli, could you please investigate?

Can you please try to first VACUUM FULL and then Cluster the table (you need free space available for that)
See
https://www.postgresql.org/docs/9.1/static/sql-cluster.html

The customer has not done a VACUUM FULL to my knowledge, but has backed up the entire database, dropped the old database, created a new database, and restored it, which produces the same result.  He's done this numerous times for both sites, most recently, yesterday at site 1.

I looked at the link above - what index should he cluster it around?  Can he do this live? I may still be able to squeeze that in today during the scheduled weekend change control if I can get concise how-to instructions to paste into the support case.

- Greg

I just tried CLUSTER vm_dynamic on my own system - not the customer one.  There's no existing index on vm_dynamic to cluster around.  I am running 4.0.

[root@rhevm2017 ~]# su - postgres
Last login: Fri Oct 21 21:35:58 CDT 2016 on pts/0
-bash-4.2$
-bash-4.2$ psql engine
psql (9.2.15)
Type "help" for help.

engine=# CLUSTER vm_dynamic;
ERROR:  there is no previously clustered index for table "vm_dynamic"
engine=# \q
-bash-4.2$

I still have my 3.6 RHEVM system - let's see if 3.6 had an existing index. Nope - same result.  So 3.5 is probably the same.

[root@rhevm2014 ~]#
[root@rhevm2014 ~]# su - postgres
-bash-4.1$ psql engine
psql (8.4.20)
Type "help" for help.

engine=# CLUSTER vm_dynamic;
ERROR:  there is no previously clustered index for table "vm_dynamic"
engine=# \q
-bash-4.1$ logout
[root@rhevm2014 ~]#

try :

CLUSTER vm_dynamic using pk_vm_dynamic;

I run also 

CLUSTER vm_dynamic;

and it runs OK as well 
Is it possible that you lost your indexes ?

please do from psql prompt  "\d vm_dynamic" and attach the complete output of it

Question - when John does VACUUM FULL in the lab, it finishes subsecond.  But the last time we tried a VACUUM ANALYZE in production, it took a long time to finish.  I imagine VACUUM FULL also will not set any speed records. What happens to other VM users while VACUUM FULL vm_dynamic is running?

Does the database lock the vm_dynamic table while that whole vacuum operation is going on, or can people get start and stop VMs s normal?

Same question for CLUSTER - while it's building its index, can users still start/stop VMs as normal?


And here is the \d output from my system here at my place.  John is working on the customer production ones.

[root@rhevm2017 ~]# su - postgres
Last login: Sun Nov 13 03:17:29 CST 2016 on pts/0
-bash-4.2$ psql engine
psql (9.2.15)
Type "help" for help.

engine=# \d vm_dynamic
                                    Table "public.vm_dynamic"
         Column         |           Type           |                  Modifiers 
                 
------------------------+--------------------------+----------------------------
-----------------
 vm_guid                | uuid                     | not null
 status                 | integer                  | not null
 vm_ip                  | text                     | 
 vm_host                | character varying(255)   | 
 vm_pid                 | integer                  | 
 last_start_time        | timestamp with time zone | 
 guest_cur_user_name    | character varying(255)   | 
 guest_os               | character varying(255)   | 
 run_on_vds             | uuid                     | 
 migrating_to_vds       | uuid                     | 
 app_list               | text                     | 
 acpi_enable            | boolean                  | 
 session                | integer                  | 
 kvm_enable             | boolean                  | 
 utc_diff               | integer                  | 
 last_vds_run_on        | uuid                     | 
 client_ip              | character varying(255)   | 
 guest_requested_memory | integer                  | 
 boot_sequence          | integer                  | 
 exit_status            | integer                  | not null default 0
 pause_status           | integer                  | not null default 0
 exit_message           | character varying(4000)  | 
 hash                   | character varying(30)    | 
 console_user_id        | uuid                     | 
 guest_agent_nics_hash  | integer                  | 
 console_cur_user_name  | character varying(255)   | 
 last_watchdog_event    | bigint                   | 
 last_watchdog_action   | character varying(8)     | 
 is_run_once            | boolean                  | not null default false
 vm_fqdn                | text                     | default ''::text
 cpu_name               | character varying(255)   | 
 last_stop_time         | timestamp with time zone | 
 current_cd             | character varying(4000)  | default NULL::character var
ying
 guest_cpu_count        | integer                  | 
 reason                 | text                     | 
 exit_reason            | integer                  | default (-1)
 emulated_machine       | character varying(255)   | 
 spice_port             | integer                  | 
 spice_tls_port         | integer                  | 
 spice_ip               | character varying(255)   | default NULL::character var
ying
 vnc_port               | integer                  | 
 vnc_ip                 | character varying(255)   | default NULL::character var
ying
 guest_agent_status     | integer                  | default 0
 guest_mem_free         | bigint                   | 
 guest_mem_buffered     | bigint                   | 
 guest_mem_cached       | bigint                   | 
 guest_timezone_offset  | integer                  | 
 guest_timezone_name    | character varying(255)   | 
 guestos_arch           | integer                  | not null default 0
 guestos_codename       | character varying(255)   | 
 guestos_distribution   | character varying(255)   | 
 guestos_kernel_version | character varying(255)   | 
 guestos_type           | character varying(255)   | not null default 'Other'::c
haracter varying
 guestos_version        | character varying(255)   | 
 guest_containers       | text                     | default '[]'::text
Indexes:
    "pk_vm_dynamic" PRIMARY KEY, btree (vm_guid)
    "idx_vm_dynamic_migrating_to_vds" btree (migrating_to_vds)
    "idx_vm_dynamic_run_on_vds" btree (run_on_vds)
Foreign-key constraints:
    "vds_static_vm_dynamic_m" FOREIGN KEY (migrating_to_vds) REFERENCES vds_stat
ic(vds_id)
    "vds_static_vm_dynamic_r" FOREIGN KEY (run_on_vds) REFERENCES vds_static(vds
_id)
    "vm_static_vm_dynamic" FOREIGN KEY (vm_guid) REFERENCES vm_static(vm_guid) O
N DELETE CASCADE

engine=#

[root@gdcpl3911 ~]# su - postgres
su: warning: cannot change directory to /usr/local/postgres: No such file or directory
-sh-4.1$ psql engine
could not change directory to "/root"
Password:
psql (8.4.20)
Type "help" for help.

engine=# \d vm_dynamic
                              Table "public.vm_dynamic"
         Column         |           Type           |            Modifiers

------------------------+--------------------------+----------------------------
-----
 vm_guid                | uuid                     | not null
 status                 | integer                  | not null
 vm_ip                  | text                     |
 vm_host                | character varying(255)   |
 vm_pid                 | integer                  |
 last_start_time        | timestamp with time zone |
 guest_cur_user_name    | character varying(255)   |
 guest_last_login_time  | timestamp with time zone |
 guest_last_logout_time | timestamp with time zone |
 guest_os               | character varying(255)   |
 run_on_vds             | uuid                     |
 migrating_to_vds       | uuid                     |
 app_list               | text                     |
 display                | integer                  |
 acpi_enable            | boolean                  |
 session                | integer                  |
 display_ip             | character varying(255)   |
 display_type           | integer                  |
 kvm_enable             | boolean                  |
 display_secure_port    | integer                  |
 utc_diff               | integer                  |
 last_vds_run_on        | uuid                     |
 client_ip              | character varying(255)   |
 guest_requested_memory | integer                  |
 hibernation_vol_handle | character varying(255)   |
 boot_sequence          | integer                  |
 exit_status            | integer                  | not null default 0
 pause_status           | integer                  | not null default 0
 exit_message           | character varying(4000)  |
 hash                   | character varying(30)    |
 console_user_id        | uuid                     |
 guest_agent_nics_hash  | integer                  |
 console_cur_user_name  | character varying(255)   |
 last_watchdog_event    | bigint                   |
 last_watchdog_action   | character varying(8)     |
 is_run_once            | boolean                  | not null default false
 vm_fqdn                | text                     | default ''::text
 cpu_name               | character varying(255)   |
 last_stop_time         | timestamp with time zone |
 current_cd             | character varying(4000)  | default NULL::character var
ying
 guest_cpu_count        | integer                  |
 reason                 | text                     |
 exit_reason            | integer                  | default (-1)
Indexes:
    "pk_vm_dynamic" PRIMARY KEY, btree (vm_guid)
    "idx_vm_dynamic_run_on_vds" btree (run_on_vds)
Foreign-key constraints:
    "vds_static_vm_dynamic_m" FOREIGN KEY (migrating_to_vds) REFERENCES vds_stat
ic(vds_id)
    "vds_static_vm_dynamic_r" FOREIGN KEY (run_on_vds) REFERENCES vds_static(vds
_id)
    "vm_static_vm_dynamic" FOREIGN KEY (vm_guid) REFERENCES vm_static(vm_guid) O
N DELETE CASCADE

engine=#

VACUUM FULL rewrites the entire contents of the table into a new disk file with no extra space, allowing unused space to be returned to the operating system. This form is much slower and requires an exclusive lock on each table while it is being processed.

When a table is being clustered, an ACCESS EXCLUSIVE lock is acquired on it. This prevents any other database operations (both reads and writes) from operating on the table until the CLUSTER is finished.

Thanks Eli - not to beat a dead horse to death, but confirm this reasoning for me.  Since both VACUUM and CLUSTER want an exclusive lock on the table in question, in this case, vm_dynamic, then any other operation on that table from anybody else will either stall or error.  Since these operations will take a long time on the large production systems, the customer should schedule them during a quiet period.  And it might be best to stop the RHEVM processes before running them.

Am I on track?

thanks

- Greg

(In reply to Greg Scott from comment #13)
> Thanks Eli - not to beat a dead horse to death, but confirm this reasoning
> for me.  Since both VACUUM and CLUSTER want an exclusive lock on the table
> in question, in this case, vm_dynamic, then any other operation on that
> table from anybody else will either stall or error.  Since these operations
> will take a long time on the large production systems, the customer should
> schedule them during a quiet period.  And it might be best to stop the RHEVM
> processes before running them.
> 
> Am I on track?

Exactly 

> 
> thanks
> 
> - Greg

I tried to work on this issue.
I created 1050 VMs in two pools. I ran over 10 VMs from the pool and restared them in random. The size of table vm_dynamic was growing with every new running VM. Then I deleted the pools. The size of the table shrank but there stayed overhead of about 120kB (without size of indexes, but they had overhead also). So the table size grew with every create/delete pools.
After running 'vacuum full' size of vm_dynamic was back few kB.

I'm sorry, I forgot to mention that I was testing it on engine 4.0.5 with postgres 9.2.18

Well, now it's obvious that we need to execute vacuum full regularly for engine and DWH databases as suggested by BZ1388430

Lucie, how long did the vacuum full take you?  When my large customer tried a vacuum (not vacuum full, just a standard vacuum) by hand earlier, it took a couple of hours. But vm_dynamic was hundreds of GB in size by then.

- Greg

(In reply to Greg Scott from comment #19)
> Lucie, how long did the vacuum full take you?  When my large customer tried
> a vacuum (not vacuum full, just a standard vacuum) by hand earlier, it took
> a couple of hours. But vm_dynamic was hundreds of GB in size by then.
> 
> - Greg

Greg, we tried to execute vacuum full on our internal medium sized setup and if I remember correctly for the first time it took around 45 minutes for DWH db and around 15 minutes for engine db. Next executions were much faster, that's why we are going to suggest to execute vacuum full each day as described in BZ1388430 (of course the interval may be customized by specific needs of the customer).

Anyway in your case I'd suggest to perform backup and restore before starting regular executions of vacuum full to make db file as clean as possible (I don't know of any other customer who would complain about that huge PostgreSQL file allocations).

(In reply to Greg Scott from comment #19)
> Lucie, how long did the vacuum full take you?  When my large customer tried
> a vacuum (not vacuum full, just a standard vacuum) by hand earlier, it took
> a couple of hours. But vm_dynamic was hundreds of GB in size by then.
> 
> - Greg

It was few minutes, I can't run all the VMs so the table was not so big. I was exploring only the grow of table size.

My customer is running a VACUUM FULL vm_dynamic; right now.  It started about 90 minutes ago, still running. And it just sits there like a bump on a log with no progress indicator.

- Greg

Statistics:

The file system with the database at this site is 251 GB.  On Nov. 5, John did a database backup, and then destroyed, recreated, and restored the database. The file system went from 82 percent used, or 194 GB before, to 9 percent after, or 21 GB used, for a savings of 173 GB.

Today is Nov. 23. The file system is 86 percent (204 GB) used, with 35GB free. So vm_dynamic piled up 183 GB of garbage in 18 days.  We just crossed 2 hours and vacuum full is still running.

The statistics above won't tell us how much longer *this* vacuum full will take, but they may be helpful for the next time.  Also, this gives us an idea for how much and how fast that vm_dynamic table grows.

- Greg

The vacuum full of vm_dynamic finished in 2 hours, 54 minutes. Just call it 3 hours. The file system went to 13 percent used, or 31 GB, not quite as nice as dropping and recreating the whole database.

Also, I can't attribute all of that 183 GB of garbage to vm_dynamic. Comparing Nov. 5 to today, it looks like around 10 GB of garbage is spread among other tables, which means vm_dynamic grew by around 173 GB over 18 days.

All in all, it looks like the workaround to drop and recreate the database is much less calendar time - John thinks he can do that in about 1/2 hour by now - and ends up with a cleaner database since we only vacuumed one table tonight.

- Greg

Greg, my assumption is that autovacuum simply falls behind and is in capable of treating the amount of garbage created. 

1. logs
 - To start investigating that lets see open the vaccum logs (do it on your lab or  the production if you can)
 put an include directive to a tweak.conf under postgres.conf and lets put all our changes there
 
 postgres.conf
   include=tweak.conf

 tweak.conf
   log_min_messages = debug1

2. Tweak the pg config to be more aggressive on vacuum
 - add this to tweak.conf:

   # set vacuum workers to the amount of busy tables
   autovacuum_max_workers = 8
   # more memory for workers, since we have 8 let raise it from the default
   maintenance_work_mem = 512MB
   # relax the threshold above the # of vms
   autovacuum_vacuum_threshold = 1200
   
   ```
   # maybe reload is enough? going with restart to be sure
   service postgresql restart
   ```

3. tweak engine
   to perform less refreshed of statistics and dynamic status writes
   ```
   engine-config -s VdsRefreshRate=6
   service ovirt-engine restart
   ```

Customer applied the database config tuning changes detailed in the KCS solution at https://access.redhat.com/solutions/2798571 over the weekend to one site.  So far, the database has not grown in size.  I'll find out more later this afternoon.

However, customer now reports these middle-of-the-night errors:

Time:2016-12-11 00:00:00.038

Message:ETL service aggregation to daily tables has encountered an error. Please consult the service log for more details.

Severity:ERROR

 

Time:2016-12-11 03:00:00.086

Message:ETL service has encountered an error while deleting old data. Please consult the service log for more details.

Severity:ERROR

We don't know yet if those are related to the database config changes.

- Greg

Greg, can you please share/check the service log as well? (it should be dwh log)

Please open a separate bug for the dwh error and attach the dwh log and a db dump.

Huh? What dwh error?

The error in comment 29 
Message:ETL service has encountered an error while deleting old data. Please consult the service log for more details. 

is a message coming from the ovirt-engine-dwhd service.
It complains that the delete job did not finish for some reason.

If this is not a one time error then please open a bug and attach required info.

Ah - thanks Shirly.  I didn't know those ETL errors were related to dwhd. So then you're right, they can't be related to the problem in this bz. And looking a little deeper, John reports these ETL errors have happened before. So that's a whole independent issue. Sorry for the distraction on this bug.

- Greg

Greg, any updates for the DB size after a few weeks?

As of the last time we talked last week, the DB size is holding steady after taking the steps in https://access.redhat.com/solutions/2798571. No scheduled customer call this week because of Christmas, but I'm sure we'll talk over the next few days.

- Greg

Changing dependency to BZ1388433, because according to results on our internal medium sized setup changes to auto vacuum configuration provided by BZ1388433 removed the need to execute full vacuum periodically. Moving bug to POST to sync with BZ1388433 status

Moving to 4.1.1 as dependent BZ1388433

Moving to MODIFIED to align status with BZ1388433

(In reply to Martin Perina from comment #39)
> Moving to MODIFIED to align status with BZ1388433
Martin, while BZ #1388433 is now targeted to 4.1.2, should we target this one accordingly?

(In reply to Gil Klein from comment #41)
> (In reply to Martin Perina from comment #39)
> > Moving to MODIFIED to align status with BZ1388433
> Martin, while BZ #1388433 is now targeted to 4.1.2, should we target this
> one accordingly?

Well, additional fixes to BZ1388433 are only "cosmetic", so even with already merged patch in 4.1.1, which changed automatic vacuum settings, you should be able to verify that no table grows out of limits on disk. But I don't have an issue with retargeting if you need to do that.

Tested on 2 pools with 1050 VMs - by starting/restarting VMs size of table vm_dynamic doesn't grow (or minimal). Sometimes little overhead (60-80k) stays after deleting the pools, but I think that this is not so common operation that I can verify it.

Feel free to reopen this bug when the table on the customer production engine still grows too much.

verified in ovirt-engine-4.1.1.8-0.1.el7.noarch